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

innodb.truncate_debug fails in buildbot

    XMLWordPrintable

    Details

      Description

      Note: the report was initially filed for 10.2, but it appears that the failure on 10.2 has gone away, while on 10.3 it is still happening, so the item has been updated to deal with 10.3 instead.

      http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest2/builds/9240/steps/test_2/logs/stdio

      innodb.truncate_debug 'innodb'           w1 [ fail ]
              Test ended at 2017-08-17 11:01:39
       
      CURRENT_TEST: innodb.truncate_debug
      --- /mnt/buildbot/build/mariadb-10.3.1/mysql-test/suite/innodb/r/truncate_debug.result	2017-08-17 09:13:54.000000000 +0300
      +++ /mnt/buildbot/build/mariadb-10.3.1/mysql-test/suite/innodb/r/truncate_debug.reject	2017-08-17 11:01:38.000000000 +0300
      @@ -76,6 +76,8 @@
       connection default;
       SET DEBUG_SYNC= 'now SIGNAL finish_scan';
       connection con1;
      +Warnings:
      +Warning	1639	debug sync point wait timed out
       disconnect con1;
       connection con2;
       disconnect con2;
       
      mysqltest: Result length mismatch
      

      The failure is reproducible locally quite well by running the test sequence which leads to it in buildbot; it can be reduced to these four tests:

      perl ./mtr --noreorder --mem compat/oracle.sp-anonymous innodb.innodb-ucs2 innodb.tmpdir innodb.truncate_debug
      

      It doesn't happen every time, but happens for me probably 4 times out of 5.
      I couldn't remove any other test from the chain, but they can be put together and further reduced to the test that I will put at the end of the description. It also shows which part is taken from which test. Basically, before innodb.truncate_debug it is just a bunch of CREATE/DROP tables.

      Both the sequence of tests and the hybrid test exhibit the same behavior. innodb.truncate_debug doesn't in fact hang on reap in connection con1; it hangs earlier, on truncate table t2 in connection default. I assume it gets somehow blocked by truncate table t1, which in turn is waiting on the sync point which is not sent, because connection default does not reach that point. After debug sync point timeout is exceeded, truncate table t1 gives up, which allows truncate table t2 to proceed and finish successfully, so all we get at the end if the misleading debug sync point wait timed out diagnostics.

      Here is what the processlist looks like while the test is waiting:

      +----+-------------+-----------------+------+---------+------+------------------------------------+-------------------+----------+
      | Id | User        | Host            | db   | Command | Time | State                              | Info              | Progress |
      +----+-------------+-----------------+------+---------+------+------------------------------------+-------------------+----------+
      |  2 | system user |                 | NULL | Daemon  | NULL | InnoDB purge worker                | NULL              |    0.000 |
      |  1 | system user |                 | NULL | Daemon  | NULL | InnoDB purge worker                | NULL              |    0.000 |
      |  3 | system user |                 | NULL | Daemon  | NULL | InnoDB purge worker                | NULL              |    0.000 |
      |  4 | system user |                 | NULL | Daemon  | NULL | InnoDB purge coordinator           | NULL              |    0.000 |
      |  5 | system user |                 | NULL | Daemon  | NULL | InnoDB shutdown handler            | NULL              |    0.000 |
      | 23 | root        | localhost       | test | Query   |  121 | NULL                               | truncate table t2 |    0.000 |
      | 24 | root        | localhost       | test | Query   |  130 | debug sync point: buffer_pool_scan | truncate table t1 |    0.000 |
      | 26 | root        | localhost:36340 | NULL | Query   |    0 | init                               | show processlist  |    0.000 |
      +----+-------------+-----------------+------+---------+------+------------------------------------+-------------------+----------+
      

      And here are the stack traces from these two threads:

      Thread 3 (Thread 0x7fb6884dd700 (LWP 2540)):
      #0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
      #1  0x000055c0515ea9e2 in os_event::wait (this=0x55c0544651b0) at /data/src/10.3/storage/innobase/os/os0event.cc:166
      #2  0x000055c0515ea3f1 in os_event::wait_low (this=0x55c0544651b0, reset_sig_count=2) at /data/src/10.3/storage/innobase/os/os0event.cc:336
      #3  0x000055c0515ea797 in os_event_wait_low (event=0x55c0544651b0, reset_sig_count=2) at /data/src/10.3/storage/innobase/os/os0event.cc:535
      #4  0x000055c051702d5c in sync_array_wait_event (arr=0x55c054273a80, cell=@0x7fb6884d9c88: 0x55c054273b50) at /data/src/10.3/storage/innobase/sync/sync0arr.cc:475
      #5  0x000055c051705e36 in rw_lock_x_lock_wait_func (lock=0x55c054465060, pass=0, threshold=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:472
      #6  0x000055c051705f9d in rw_lock_x_lock_low (lock=0x55c054465060, pass=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:536
      #7  0x000055c0517063ff in rw_lock_x_lock_func (lock=0x55c054465060, pass=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:687
      #8  0x000055c0517858fe in pfs_rw_lock_x_lock_func (lock=0x55c054465060, pass=0, file_name=0x55c051cefa50 "/data/src/10.3/storage/innobase/include/btr0sea.ic", line=96) at /data/src/10.3/storage/innobase/include/sync0rw.ic:539
      #9  0x000055c05178de9f in btr_search_x_lock (index=0x55c054930e68) at /data/src/10.3/storage/innobase/include/btr0sea.ic:96
      #10 0x000055c051798122 in btr_cur_update_in_place (flags=2, cursor=0x7fb63c0d4428, offsets=0x7fb6884da640, update=0x7fb63c0d45f8, cmpl_info=0, thr=0x7fb63c0d6858, trx_id=1863, mtr=0x7fb6884da960) at /data/src/10.3/storage/innobase/btr/btr0cur.cc:3706
      #11 0x000055c0517989af in btr_cur_optimistic_update (flags=2, cursor=0x7fb63c0d4428, offsets=0x7fb6884da540, heap=0x7fb6884da5e8, update=0x7fb63c0d45f8, cmpl_info=0, thr=0x7fb63c0d6858, trx_id=1863, mtr=0x7fb6884da960) at /data/src/10.3/storage/innobase/btr/btr0cur.cc:3832
      #12 0x000055c0516e150f in row_upd_clust_rec (flags=0, node=0x7fb63c0d3dd0, index=0x55c054930e68, offsets=0x7fb6884da640, offsets_heap=0x7fb6884da5e8, thr=0x7fb63c0d6858, mtr=0x7fb6884da960) at /data/src/10.3/storage/innobase/row/row0upd.cc:2845
      #13 0x000055c0516e26e6 in row_upd_clust_step (node=0x7fb63c0d3dd0, thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/row/row0upd.cc:3211
      #14 0x000055c0516e29a6 in row_upd (node=0x7fb63c0d3dd0, thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/row/row0upd.cc:3273
      #15 0x000055c0516e2e9d in row_upd_step (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/row/row0upd.cc:3417
      #16 0x000055c051621779 in que_thr_step (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/que/que0que.cc:1036
      #17 0x000055c051621a81 in que_run_threads_low (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/que/que0que.cc:1116
      #18 0x000055c051621c63 in que_run_threads (thr=0x7fb63c0d6858) at /data/src/10.3/storage/innobase/que/que0que.cc:1156
      #19 0x000055c051621f04 in que_eval_sql (info=0x7fb63c0b3288, sql=0x55c051ca9330 "PROCEDURE RENUMBER_TABLE_ID_PROC () IS\nBEGIN\nUPDATE SYS_TABLES SET ID = :new_id\n WHERE ID = :old_id;\nUPDATE SYS_COLUMNS SET TABLE_ID = :new_id\n WHERE TABLE_ID = :old_id;\nUPDATE SYS_INDEXES SET TABLE_I"..., reserve_dict_mutex=0, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/que/que0que.cc:1233
      #20 0x000055c0516c48b5 in row_truncate_update_table_id (old_table_id=82, new_table_id=85, reserve_dict_mutex=0, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/row/row0trunc.cc:1402
      #21 0x000055c0516c4bda in row_truncate_update_system_tables (table=0x7fb63c033148, new_id=85, has_internal_doc_id=false, no_redo=true, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/row/row0trunc.cc:1525
      #22 0x000055c0516c5f9d in row_truncate_table_for_mysql (table=0x7fb63c033148, trx=0x7fb688777878) at /data/src/10.3/storage/innobase/row/row0trunc.cc:2086
      #23 0x000055c05152b68d in ha_innobase::truncate (this=0x7fb63c0b37e8) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:13374
      #24 0x000055c051200b59 in handler::ha_truncate (this=0x7fb63c0b37e8) at /data/src/10.3/sql/handler.cc:4101
      #25 0x000055c0513d3cdc in Sql_cmd_truncate_table::handler_truncate (this=0x7fb63c0150f0, thd=0x7fb63c000b00, table_ref=0x7fb63c014ad8, is_tmp_table=false) at /data/src/10.3/sql/sql_truncate.cc:246
      #26 0x000055c0513d43a6 in Sql_cmd_truncate_table::truncate_table (this=0x7fb63c0150f0, thd=0x7fb63c000b00, table_ref=0x7fb63c014ad8) at /data/src/10.3/sql/sql_truncate.cc:445
      #27 0x000055c0513d4518 in Sql_cmd_truncate_table::execute (this=0x7fb63c0150f0, thd=0x7fb63c000b00) at /data/src/10.3/sql/sql_truncate.cc:502
      #28 0x000055c050f40233 in mysql_execute_command (thd=0x7fb63c000b00) at /data/src/10.3/sql/sql_parse.cc:6235
      #29 0x000055c050f44b2a in mysql_parse (thd=0x7fb63c000b00, rawbuf=0x7fb63c014a08 "truncate table t2", length=17, parser_state=0x7fb6884dc610, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7921
      #30 0x000055c050f32284 in dispatch_command (command=COM_QUERY, thd=0x7fb63c000b00, packet=0x7fb63c08f821 "truncate table t2", packet_length=17, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1819
      #31 0x000055c050f30ce6 in do_command (thd=0x7fb63c000b00) at /data/src/10.3/sql/sql_parse.cc:1370
      #32 0x000055c051087668 in do_handle_one_connection (connect=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1418
      #33 0x000055c0510873f5 in handle_one_connection (arg=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1324
      #34 0x000055c0514fee7a in pfs_spawn_thread (arg=0x55c0547a3940) at /data/src/10.3/storage/perfschema/pfs.cc:1862
      #35 0x00007fb690790494 in start_thread (arg=0x7fb6884dd700) at pthread_create.c:333
      #36 0x00007fb68e90893f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      Thread 2 (Thread 0x7fb688493700 (LWP 2559)):
      #0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
      #1  0x000055c0519cce91 in safe_cond_timedwait (cond=0x55c0525e81a0 <debug_sync_global+32>, mp=0x55c0525e81d8 <debug_sync_global+88>, abstime=0x7fb688490c60, file=0x55c051a64d40 "/data/src/10.3/include/mysql/psi/mysql_thread.h", line=1175) at /data/src/10.3/mysys/thr_mutex.c:546
      #2  0x000055c050f6567f in inline_mysql_cond_timedwait (that=0x55c0525e81a0 <debug_sync_global+32>, mutex=0x55c0525e81d8 <debug_sync_global+88>, abstime=0x7fb688490c60, src_file=0x55c051a64e58 "/data/src/10.3/sql/debug_sync.cc", src_line=1444) at /data/src/10.3/include/mysql/psi/mysql_thread.h:1175
      #3  0x000055c050f68726 in debug_sync_execute (thd=0x7fb628000b00, action=0x7fb628008090) at /data/src/10.3/sql/debug_sync.cc:1444
      #4  0x000055c050f68d33 in debug_sync (thd=0x7fb628000b00, sync_point_name=0x55c051d3a378 "buffer_pool_scan", name_len=16) at /data/src/10.3/sql/debug_sync.cc:1552
      #5  0x000055c05186344f in fil_reinit_space_header_for_table (table=0x7fb63c0b02f8, size=8, trx=0x7fb688777ca8) at /data/src/10.3/storage/innobase/fil/fil0fil.cc:3322
      #6  0x000055c0516c5d36 in row_truncate_table_for_mysql (table=0x7fb63c0b02f8, trx=0x7fb688777ca8) at /data/src/10.3/storage/innobase/row/row0trunc.cc:2018
      #7  0x000055c05152b68d in ha_innobase::truncate (this=0x7fb62801cf18) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:13374
      #8  0x000055c051200b59 in handler::ha_truncate (this=0x7fb62801cf18) at /data/src/10.3/sql/handler.cc:4101
      #9  0x000055c0513d3cdc in Sql_cmd_truncate_table::handler_truncate (this=0x7fb628013d30, thd=0x7fb628000b00, table_ref=0x7fb628013718, is_tmp_table=false) at /data/src/10.3/sql/sql_truncate.cc:246
      #10 0x000055c0513d43a6 in Sql_cmd_truncate_table::truncate_table (this=0x7fb628013d30, thd=0x7fb628000b00, table_ref=0x7fb628013718) at /data/src/10.3/sql/sql_truncate.cc:445
      #11 0x000055c0513d4518 in Sql_cmd_truncate_table::execute (this=0x7fb628013d30, thd=0x7fb628000b00) at /data/src/10.3/sql/sql_truncate.cc:502
      #12 0x000055c050f40233 in mysql_execute_command (thd=0x7fb628000b00) at /data/src/10.3/sql/sql_parse.cc:6235
      #13 0x000055c050f44b2a in mysql_parse (thd=0x7fb628000b00, rawbuf=0x7fb628013648 "truncate table t1", length=17, parser_state=0x7fb688492610, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7921
      #14 0x000055c050f32284 in dispatch_command (command=COM_QUERY, thd=0x7fb628000b00, packet=0x7fb62800af11 "truncate table t1", packet_length=17, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1819
      #15 0x000055c050f30ce6 in do_command (thd=0x7fb628000b00) at /data/src/10.3/sql/sql_parse.cc:1370
      #16 0x000055c051087668 in do_handle_one_connection (connect=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1418
      #17 0x000055c0510873f5 in handle_one_connection (arg=0x55c05479b000) at /data/src/10.3/sql/sql_connect.cc:1324
      #18 0x000055c0514fee7a in pfs_spawn_thread (arg=0x55c0547a3cf0) at /data/src/10.3/storage/perfschema/pfs.cc:1862
      #19 0x00007fb690790494 in start_thread (arg=0x7fb688493700) at pthread_create.c:333
      #20 0x00007fb68e90893f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      I can't get SHOW ENGINE INNODB STATUS because it is blocked too; but after 240 seconds it starts complaining about long semaphore wait, which leads to dumping the monitor information to the error log:

      2017-09-25 16:31:18 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140421947578112 has waited at btr0sea.ic line 96 for 241.00 seconds the semaphore:
      X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193
      a writer (thread id 140421947578112) has reserved it in mode  wait exclusive
      number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-09-25 16:31:18 0 [Note] InnoDB: A semaphore wait:
      --Thread 140421947578112 has waited at btr0sea.ic line 96 for 241.00 seconds the semaphore:
      X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193
      a writer (thread id 140421947578112) has reserved it in mode  wait exclusive
      number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-09-25 16:31:18 0 [Note] InnoDB: A semaphore wait:
      --Thread 140421690791680 has waited at srv0srv.cc line 2116 for 239.00 seconds the semaphore:
      X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112
      a writer (thread id 140421947578112) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 927
      Last time write locked in file fil0fil.cc line 3326
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
       
      =====================================
      2017-09-25 16:31:27 0x7fb67a7fc700 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 16 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 3 srv_active, 0 srv_shutdown, 9 srv_idle
      srv_master_thread log flush and writes: 11
      ----------
      SEMAPHORES
      ----------
      -------------
      RW-LATCH INFO
      -------------
      RW-LOCK: 0x55c05492b5e0  Waiters for the lock exist
      Locked: thread 140421947578112 file fil0fil.cc line 3326  X-LOCK
      RW-LOCK: 0x55c054465230 
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x55c054465060 
      Locked: thread 140421947578112 file btr0sea.ic line 96  WAIT X-LOCK
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x55c054464e90 
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x55c054464cc0 
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x55c054464af0 
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x55c054464920 
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x55c054464750 
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x55c054464580 
      Locked: thread 140421947275008 file btr0sea.ic line 152  S-LOCK
      RW-LOCK: 0x7fb6837b6028 
      Locked: thread 140421947578112 file row0upd.cc line 3096  S-LOCK
      RW-LOCK: 0x7fb6837b5ef8 
      Locked: thread 140421947578112 file row0upd.cc line 3096  X-LOCK
      Total number of rw-locks 1085
      OS WAIT ARRAY INFO: reservation count 250
      --Thread 140421947578112 has waited at btr0sea.ic line 96 for 250.00 seconds the semaphore:
      X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193
      a writer (thread id 140421947578112) has reserved it in mode  wait exclusive
      number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      --Thread 140421690791680 has waited at srv0srv.cc line 2116 for 248.00 seconds the semaphore:
      X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112
      a writer (thread id 140421947578112) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 927
      Last time write locked in file fil0fil.cc line 3326
      OS WAIT ARRAY INFO: signal count 262
      RW-shared spins 0, rounds 504, OS waits 89
      RW-excl spins 0, rounds 1489, OS waits 8
      RW-sx spins 0, rounds 0, OS waits 0
      Spin rounds per wait: 504.00 RW-shared, 1489.00 RW-excl, 0.00 RW-sx
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 1864
      Purge done for trx's n:o < 1863 undo n:o < 0 state: running but idle
      History list length 41
      Total number of lock structs in row lock hash table 2
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 1863, ACTIVE 250 sec truncating table
      mysql tables in use 1, locked 1
      3 lock struct(s), heap size 1160, 2 row lock(s), undo log entries 1
      MySQL thread id 23, OS thread handle 0x7fb6884dd700, query id 552 localhost root
      truncate table t2
      ---TRANSACTION 1860, ACTIVE 259 sec truncating table
      mysql tables in use 1, locked 1
      0 lock struct(s), heap size 1160, 0 row lock(s)
      MySQL thread id 24, OS thread handle 0x7fb688493700, query id 537 localhost root debug sync point: buffer_pool_scan
      truncate table t1
      InnoDB: ###### Diagnostic info printed to the standard error stream
      2017-09-25 16:31:49 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140421947578112 has waited at btr0sea.ic line 96 for 272.00 seconds the semaphore:
      X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193
      a writer (thread id 140421947578112) has reserved it in mode  wait exclusive
      number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-09-25 16:31:49 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140421690791680 has waited at srv0srv.cc line 2116 for 270.00 seconds the semaphore:
      X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112
      a writer (thread id 140421947578112) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 927
      Last time write locked in file fil0fil.cc line 3326
      2017-09-25 16:31:49 0 [Note] InnoDB: A semaphore wait:
      --Thread 140421947578112 has waited at btr0sea.ic line 96 for 272.00 seconds the semaphore:
      X-lock (wait_ex) on RW-latch at 0x55c054465060 created in file btr0sea.cc line 193
      a writer (thread id 140421947578112) has reserved it in mode  wait exclusive
      number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
      Last time read locked in file btr0sea.ic line 152
      Last time write locked in file btr0sea.ic line 96
      2017-09-25 16:31:49 0 [Note] InnoDB: A semaphore wait:
      --Thread 140421715969792 has waited at lock0lock.cc line 6573 for 22.00 seconds the semaphore:
      X-lock on RW-latch at 0x7fb6837b5ef8 created in file buf0buf.cc line 1460
      a writer (thread id 140421947578112) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0sel.cc line 915
      Last time write locked in file row0upd.cc line 3096
      2017-09-25 16:31:49 0 [Note] InnoDB: A semaphore wait:
      --Thread 140421690791680 has waited at srv0srv.cc line 2116 for 270.00 seconds the semaphore:
      X-lock on RW-latch at 0x55c05492b5e0 created in file dict0dict.cc line 1112
      a writer (thread id 140421947578112) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0purge.cc line 927
      Last time write locked in file fil0fil.cc line 3326
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
      --------
      FILE I/O
      --------
      I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
      I/O thread 1 state: waiting for completed aio requests (log thread)
      I/O thread 2 state: waiting for completed aio requests (read thread)
      I/O thread 3 state: waiting for completed aio requests (read thread)
      I/O thread 4 state: waiting for completed aio requests (write thread)
      I/O thread 5 state: waiting for completed aio requests (write thread)
      Pending normal aio reads: [0, 0] , aio writes: [0, 0] ,
       ibuf aio reads:, log i/o's:, sync i/o's:
      Pending flushes (fsync) log: 0; buffer pool: 0
      292 OS file reads, 848 OS file writes, 459 OS fsyncs
      0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
      -------------------------------------
      INSERT BUFFER AND ADAPTIVE HASH INDEX
      -------------------------------------
      Ibuf: size 1, free list len 0, seg size 2, 3 merges
      merged operations:
       insert 0, delete mark 0, delete 0
      discarded operations:
       insert 0, delete mark 0, delete 0
      Hash table size 2267, used cells 0, node heap has 0 buffer(s)
      Hash table size 2267, used cells 0, node heap has 0 buffer(s)
      Hash table size 2267, used cells 0, node heap has 0 buffer(s)
      Hash table size 2267, used cells 0, node heap has 0 buffer(s)
      Hash table size 2267, used cells 0, node heap has 0 buffer(s)
      Hash table size 2267, used cells 0, node heap has 0 buffer(s)
      Hash table size 2267, used cells 10, node heap has 1 buffer(s)
      Hash table size 2267, used cells 0, node heap has 0 buffer(s)
      0.00 hash searches/s, 0.31 non-hash searches/s
      ---
      LOG
      ---
      Log sequence number 2102801
      Log flushed up to   2102648
      Pages flushed up to 2102648
      Last checkpoint at  2098486
      0 pending log flushes, 0 pending chkp writes
      295 log i/o's done, 0.00 log i/o's/second
      ----------------------
      BUFFER POOL AND MEMORY
      ----------------------
      Total large memory allocated 8814592
      Dictionary memory allocated 95167
      Buffer pool size   512
      Free buffers       115
      Database pages     396
      Old database pages 0
      Modified db pages  7
      Percent of dirty pages(LRU & free pages): 1.367
      Max dirty pages percent: 75.000
      Pending reads 0
      Pending writes: LRU 0, flush list 0, single page 0
      Pages made young 0, not young 322
      0.00 youngs/s, 0.00 non-youngs/s
      Pages read 276, created 520, written 468
      0.00 reads/s, 0.00 creates/s, 0.00 writes/s
      Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
      Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
      LRU len: 396, unzip_LRU len: 0
      I/O sum[0]:cur[0], unzip sum[0]:cur[0]
      --------------
      ROW OPERATIONS
      --------------
      0 queries inside InnoDB, 0 queries in queue
      0 read views open inside InnoDB
      Process ID=2511, Main thread ID=140421690791680, state: making checkpoint
      Number of rows inserted 199, updated 42, deleted 0, read 272
      0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
      Number of system rows inserted 0, updated 0, deleted 0, read 0
      0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
      ----------------------------
      END OF INNODB MONITOR OUTPUT
      ============================
      

      This is the essential part of the test sequence which leads to the same failure (with approximately the same frequency):

      --source include/have_innodb.inc
      --source include/have_debug_sync.inc
       
      #########################################################
      # sp-anonymous.test
       
      CREATE TABLE t1 (a INT NOT NULL PRIMARY KEY) ENGINE=InnoDB;
      DROP TABLE t1;
       
      #########################################################
      # innodb-ucs2.test
       
      --disable_warnings
      drop table if exists t1, t2;
      --enable_warnings
       
      create table t1 (
        a int, b text(10), c text(10), filler text(10), primary key(a, b(2)), unique key (a, c(2))
      ) character set utf8 engine = innodb;
      drop table t1;
       
      create table t1 (
        a int, b blob(10), c blob(10), filler blob(10), primary key(a, b(2)), unique key (a, c(2))
      ) character set utf8 engine = innodb;
      create table t2 (
        a int, b blob(10), c blob(10), filler blob(10), primary key(a, b(2)), unique key (a, c(2))
      ) character set ucs2 engine = innodb;
      drop table t1;
      drop table t2;
      commit;
       
      create table t2 (
        a int, b char(10), filler char(10), primary key(a, b(2)) 
      ) character set utf8 engine = innodb;
      drop table t2;
       
      create table t2 (
        a int, b char(10), filler char(10), primary key(a, b(2)) 
      ) character set ucs2 engine = innodb;
      drop table t2;
       
      create table t1(a int not null, b char(110),primary key(a,b(100))) engine=innodb default charset=utf8;
      drop table t1;
       
      create table t1(a int not null, b text(110),primary key(a,b(100))) engine=innodb default charset=utf8;
      drop table t1;
       
      --echo End of 5.0 tests
       
       
      #########################################################################
      # innodb.tmpdir.test
       
      create table t1(a int primary key)engine=innodb;
      drop table t1;
       
      create table t1(a text, b text, fulltext(a,b))engine=innodb;
      insert into t1 values('test1', 'test2');
      alter table t1 add fulltext(b);
      drop table t1;
       
      ##############################################################
      # innodb.truncate_debug.test
       
      --source include/count_sessions.inc
       
      create table t1 (f1 int,f2 int,key(f2),f3 int) engine=innodb;
      create table t2 (f1 int,f2 int,key(f2),f3 int) engine=innodb;
       
      SET session lock_wait_timeout = 1;
       
      connect (con1,localhost,root,,);
      SET DEBUG_SYNC= 'buffer_pool_scan SIGNAL started WAIT_FOR finish_scan';
      send truncate table t1;
       
      connection default;
      SET DEBUG_SYNC= 'now WAIT_FOR started';
       
      --echo Concurrent truncate on other tables
      truncate table t2;
       
      connection default;
      SET DEBUG_SYNC= 'now SIGNAL finish_scan';
       
      connection con1;
      reap;
      disconnect con1;
       
      connection default;
      SET DEBUG_SYNC= 'RESET';
       
      SET session lock_wait_timeout=default;
       
      drop table t1,t2;
      --source include/wait_until_count_sessions.inc
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              marko Marko Mäkelä
              Reporter:
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Git Integration