Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-8890

Server gets locked after killing ANALYZE INSERT/REPLACE DELAYED

    XMLWordPrintable

    Details

      Description

      Note: see also MDEV-8889, they might be somehow related.

      The test runs ANALYZE REPLACE DELAYED and kills some of these queries in a rapid fashion. Soon after the start the flow gets stuck, and the processlist looks like this:

      +----+---------+-----------------+-------+----------------+------+------------------------------+-------------------------------------------------------------------------+----------+
      | Id | User    | Host            | db    | Command        | Time | State                        | Info                                                                    | Progress |
      +----+---------+-----------------+-------+----------------+------+------------------------------+-------------------------------------------------------------------------+----------+
      |  2 | rqg     | localhost:33215 | mysql | Sleep          |   53 |                              | NULL                                                                    |    0.000 |
      |  8 | rqg     | localhost:33221 | test  | Sleep          |    0 |                              | NULL                                                                    |    0.000 |
      |  9 | rqg     | localhost:33222 | test  | Killed         |   32 | waiting for handler insert   | ANALYZE REPLACE DELAYED INTO `BB` ( `col_varchar_key` ) VALUES ( NULL ) |    0.000 |
      | 10 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 11 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 12 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 13 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 14 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 15 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 16 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for table level lock |                                                                         |    0.000 |
      | 17 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 18 | rqg     | localhost:33223 | test  | Killed         |   31 | waiting for handler insert   | ANALYZE REPLACE DELAYED INTO `BB` ( `col_time_nokey` ) VALUES ( NULL )  |    0.000 |
      | 19 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 20 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 21 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 22 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 23 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for table level lock |                                                                         |    0.000 |
      | 24 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for INSERT           |                                                                         |    0.000 |
      | 25 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for table level lock |                                                                         |    0.000 |
      | 26 | DELAYED | localhost       | test  | Delayed insert | NULL | Waiting for table level lock |                                                                         |    0.000 |
      | 27 | root    | localhost:38193 | test  | Query          |    0 | init                         | show processlist                                                        |    0.000 |
      +----+---------+-----------------+-------+----------------+------+------------------------------+-------------------------------------------------------------------------+----------+

      If lock_wait_timeout is set to a reasonable value, eventually the timeout is reached, and the hanging ANALYZE queries die, along with some of DELAYED connections; but some DELAYED stay:

      MariaDB [test]> show processlist;
      +----+---------+-----------------+------+----------------+------+--------------------+------------------+----------+
      | Id | User    | Host            | db   | Command        | Time | State              | Info             | Progress |
      +----+---------+-----------------+------+----------------+------+--------------------+------------------+----------+
      | 10 | DELAYED | localhost       | test | Killed         | NULL | Waiting for INSERT |                  |    0.000 |
      | 11 | DELAYED | localhost       | test | Killed         | NULL | Waiting for INSERT |                  |    0.000 |
      | 13 | DELAYED | localhost       | test | Killed         | NULL | Waiting for INSERT |                  |    0.000 |
      | 14 | DELAYED | localhost       | test | Killed         | NULL | Waiting for INSERT |                  |    0.000 |
      | 16 | DELAYED | localhost       | test | Delayed insert | NULL | Waiting for INSERT |                  |    0.000 |
      | 17 | DELAYED | localhost       | test | Killed         | NULL | Waiting for INSERT |                  |    0.000 |
      | 23 | DELAYED | localhost       | test | Delayed insert | NULL | Waiting for INSERT |                  |    0.000 |
      | 25 | DELAYED | localhost       | test | Delayed insert | NULL | Waiting for INSERT |                  |    0.000 |
      | 26 | DELAYED | localhost       | test | Delayed insert | NULL | Waiting for INSERT |                  |    0.000 |
      | 27 | root    | localhost:38193 | test | Query          |    0 | init               | show processlist |    0.000 |
      +----+---------+-----------------+------+----------------+------+--------------------+------------------+----------+

      And further the server hangs on shutdown. Two thread stacks taken with a few seconds interval are attached, here is the diff:

      Stack traces from 10.1 commit a84fae27d9badef8cc89b1369a90cfef1dc3c715

      < #2  0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813478905) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
      ---
      > #2  0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813522777) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
      216c216
      < #2  0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813478918) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
      ---
      > #2  0x00007f85a72d50ed in page_cleaner_sleep_if_needed (next_loop_time=1443813522792) at 10.1/storage/xtradb/buf/buf0flu.cc:2644
      278,285d277
      < #0  safe_mutex_unlock (mp=0x7f85a8010da0, file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", line=2886) at 10.1/mysys/thr_mutex.c:452
      < #1  0x00007f85a6cb30d9 in inline_mysql_mutex_unlock (that=0x7f85a8010da0, src_file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", src_line=2886) at 10.1/include/mysql/psi/mysql_thread.h:761
      < #2  0x00007f85a6cb9c19 in handle_delayed_insert (arg=0x7f857fca2070) at 10.1/sql/sql_insert.cc:2886
      < #3  0x00007f85a63a9b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
      < #4  0x00007f85a423595d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      < #5  0x0000000000000000 in ?? ()
      < 
      < Thread 9 (Thread 0x7f85a4110700 (LWP 5137)):
      291c283
      < #5  0x00007f85a6cb9be3 in handle_delayed_insert (arg=0x7f857fcae070) at 10.1/sql/sql_insert.cc:2883
      ---
      > #5  0x00007f85a6cb9be3 in handle_delayed_insert (arg=0x7f857fca2070) at 10.1/sql/sql_insert.cc:2883
      294a287,296
      > 
      > Thread 9 (Thread 0x7f85a4110700 (LWP 5137)):
      > #0  0x00007f85a63ad69e in __pthread_mutex_unlock_usercnt (mutex=0x7f85a8885100, decr=<optimized out>) at pthread_mutex_unlock.c:52
      > #1  0x00007f85a7588f63 in _db_doprnt_ (format=0x7f85a78acb60 "%s (0x%lx) unlocking") at 10.1/dbug/dbug.c:1284
      > #2  0x00007f85a756e5ec in safe_mutex_unlock (mp=0x7f857fcb3478, file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", line=2882) at 10.1/mysys/thr_mutex.c:409
      > #3  0x00007f85a6cb30d9 in inline_mysql_mutex_unlock (that=0x7f857fcb3478, src_file=0x7f85a7633ce0 "10.1/sql/sql_insert.cc", src_line=2882) at 10.1/include/mysql/psi/mysql_thread.h:761
      > #4  0x00007f85a6cb9bc8 in handle_delayed_insert (arg=0x7f857fcae070) at 10.1/sql/sql_insert.cc:2882
      > #5  0x00007f85a63a9b50 in start_thread (arg=<optimized out>) at pthread_create.c:304
      > #6  0x00007f85a423595d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
      > #7  0x0000000000000000 in ?? ()

      RQG grammar test.yy

      thread1:
      	SELECT Id INTO @kill_id FROM INFORMATION_SCHEMA.PROCESSLIST WHERE Info LIKE 'ANALYZE REPLACE DELAYED%' LIMIT 1; KILL QUERY @kill_id ;
       
      query:
      	ANALYZE REPLACE DELAYED INTO _table ( _field ) VALUES ( NULL ) ;

      RQG command line

      perl ./runall-new.pl --threads=3 --duration=300 --queries=100M --grammar=test.yy --engine=MyISAM --basedir1=<your basedir> --vardir1=<your vardir>

      For RQG, I recommend using lp:~elenst/randgen/mariadb-patches

        Attachments

        1. threads1
          32 kB
        2. threads2
          33 kB

          Activity

            People

            Assignee:
            psergey Sergei Petrunia
            Reporter:
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated: