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

InnoDB hangs when setting innodb_adaptive_hash_index=OFF during UPDATE

Details

    Description

      Run with --mem --repeat=N. On my machine, N=10 is pretty much always enough. On perro, it took a few more.

      --source include/have_innodb.inc
       
      --connect (con1,localhost,root,,test)
      CREATE TABLE t1 (f INT, KEY(f)) ENGINE=InnoDB;
      INSERT INTO t1 VALUES (),(),(),(),(),(),(),();
      UPDATE t1 SET f = 8;
      UPDATE t1 SET f = 4;
      UPDATE t1 SET f = 6;
      UPDATE t1 SET f = 8;
      UPDATE t1 SET f = 2;
      UPDATE t1 SET f = 9;
      UPDATE t1 SET f = 3;
      UPDATE t1 SET f = 4;
      UPDATE t1 SET f = 6;
      CREATE TABLE t2 (n DECIMAL) ENGINE=InnoDB;
      UPDATE t1 SET f = 0;
      UPDATE t1 SET f = 1;
      UPDATE t1 SET f = 5;
      ALTER TABLE t2 ADD COLUMN i INT;
      UPDATE t1 SET f = 2;
      --send
      	ALTER TABLE t2 ADD COLUMN v INT AS (i) VIRTUAL;
       
      --connection default
      UPDATE t1 SET f = 6;
       
      --connection con1
      --reap
       
      # Cleanup
      --disconnect con1
      --connection default
      DROP TABLE t2, t1;
      

      The explicit "DEADLOCK of threads detected" failure I was mostly getting in initial concurrent tests; it's still achievable with the test case above, although rarely. More often I get a hang which ends up in the long semaphore wait abort.

      DEADLOCK of threads detected variation

      All threads' stack trace is attached as threads

      10.3 c029eae02d5d94a

      Version: '10.3.3-MariaDB-debug-log'  socket: '/data/bld/10.3/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
      CURRENT_TEST: bug.t9i
      ########################################
      DEADLOCK of threads detected!
      rw-lock 0x55bd3e204f00 --Thread 139629613262592 has waited at btr0sea.ic line 96 for 0.00 seconds the semaphore:
      X-lock on RW-latch at 0x55bd3e204f00 created in file btr0sea.cc line 260
      a writer (thread id 139629925762816) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      Locked: thread 139629925762816 file btr0sea.ic line 96  X-LOCK
      Locked: thread 139629925762816 file btr0sea.ic line 96  X-LOCK
      rw-lock 0x7efe21cddcc8 --Thread 139629630048000 has waited at row0row.cc line 1030 for 0.00 seconds the semaphore:
      X-lock on RW-latch at 0x7efe21cddcc8 created in file buf0buf.cc line 1461
      a writer (thread id 139629613262592) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file row0row.cc line 1030
      Last time write locked in file row0row.cc line 1030
      Locked: thread 139629613262592 file row0row.cc line 1030  X-LOCK
      Locked: thread 139629613262592 file row0row.cc line 1030  X-LOCK
      rw-lock 0x55bd3e6cb6d0 --Thread 139629925762816 has waited at row0mysql.cc line 3597 for 0.00 seconds the semaphore:
      X-lock (wait_ex) on RW-latch at 0x55bd3e6cb6d0 created in file dict0dict.cc line 1109
      a writer (thread id 139629925762816) has reserved it in mode  wait exclusive
      number of readers 3, waiters flag 0, lock_word: fffffffffffffffd
      Last time read locked in file row0purge.cc line 928
      Last time write locked in file handler0alter.cc line 9152
      Locked: thread 139629630048000 file row0purge.cc line 928  S-LOCK
      Locked: thread 139629630048000 file row0purge.cc line 928  S-LOCK
      2017-11-19 23:56:02 14 [ERROR] [FATAL] InnoDB: ######################################## Deadlock Detected!
      171119 23:56:02 [ERROR] mysqld got signal 6 ;
      

      #5  0x00007efe2860a3fa in abort () from /lib/x86_64-linux-gnu/libc.so.6
      #6  0x000055bd3b9857d3 in ib::fatal::~fatal (this=0x7efe201fb6a0, __in_chrg=<optimized out>) at /data/src/10.3/storage/innobase/ut/ut0ut.cc:850
      #7  0x000055bd3b926941 in sync_array_wait_event (arr=0x55bd3e013a30, cell=@0x7efe201fb858: 0x55bd3e013b80) at /data/src/10.3/storage/innobase/sync/sync0arr.cc:468
      #8  0x000055bd3b929a6c in rw_lock_x_lock_wait_func (lock=0x55bd3e6cb6d0, pass=0, threshold=0, file_name=0x55bd3bee7980 "/data/src/10.3/storage/innobase/row/row0mysql.cc", line=3597) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:479
      #9  0x000055bd3b929bd3 in rw_lock_x_lock_low (lock=0x55bd3e6cb6d0, pass=0, file_name=0x55bd3bee7980 "/data/src/10.3/storage/innobase/row/row0mysql.cc", line=3597) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:543
      #10 0x000055bd3b92a035 in rw_lock_x_lock_func (lock=0x55bd3e6cb6d0, pass=0, file_name=0x55bd3bee7980 "/data/src/10.3/storage/innobase/row/row0mysql.cc", line=3597) at /data/src/10.3/storage/innobase/sync/sync0rw.cc:694
      #11 0x000055bd3b89acd9 in pfs_rw_lock_x_lock_func (lock=0x55bd3e6cb6d0, pass=0, file_name=0x55bd3bee7980 "/data/src/10.3/storage/innobase/row/row0mysql.cc", line=3597) at /data/src/10.3/storage/innobase/include/sync0rw.ic:549
      #12 0x000055bd3b8a35d8 in row_mysql_lock_data_dictionary_func (trx=0x7efe22505878, file=0x55bd3bee7980 "/data/src/10.3/storage/innobase/row/row0mysql.cc", line=3597) at /data/src/10.3/storage/innobase/row/row0mysql.cc:2361
      #13 0x000055bd3b8a6393 in row_drop_table_for_mysql (name=0x7efe201fc690 "test/t2", trx=0x7efe22505878, drop_db=false, create_failed=0, nonatomic=true) at /data/src/10.3/storage/innobase/row/row0mysql.cc:3597
      #14 0x000055bd3b750edb in ha_innobase::delete_table (this=0x7efdd0015c20, name=0x7efe201fe210 "./test/t2") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:13379
      #15 0x000055bd3b42239c in handler::ha_delete_table (this=0x7efdd0015c20, name=0x7efe201fe210 "./test/t2") at /data/src/10.3/sql/handler.cc:4358
      #16 0x000055bd3b41c725 in ha_delete_table (thd=0x7efdd0000b00, table_type=0x55bd3df308d0, path=0x7efe201fe210 "./test/t2", db=0x7efdd0015178 "test", alias=0x7efdd0014b30 "t2", generate_warning=true) at /data/src/10.3/sql/handler.cc:2359
      #17 0x000055bd3b216ea8 in mysql_rm_table_no_locks (thd=0x7efdd0000b00, tables=0x7efdd0014b68, if_exists=false, drop_temporary=false, drop_view=false, drop_sequence=false, dont_log_query=false, dont_free_locks=false) at /data/src/10.3/sql/sql_table.cc:2507
      #18 0x000055bd3b215ec4 in mysql_rm_table (thd=0x7efdd0000b00, tables=0x7efdd0014b68, if_exists=false, drop_temporary=false, drop_sequence=false) at /data/src/10.3/sql/sql_table.cc:2119
      #19 0x000055bd3b155bf8 in mysql_execute_command (thd=0x7efdd0000b00) at /data/src/10.3/sql/sql_parse.cc:5020
      #20 0x000055bd3b15ecee in mysql_parse (thd=0x7efdd0000b00, rawbuf=0x7efdd0014a98 "DROP TABLE t2, t1", length=17, parser_state=0x7efe201ff610, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7933
      #21 0x000055bd3b14c6ce in dispatch_command (command=COM_QUERY, thd=0x7efdd0000b00, packet=0x7efdd0093e71 "DROP TABLE t2, t1", packet_length=17, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1828
      #22 0x000055bd3b14b0ef in do_command (thd=0x7efdd0000b00) at /data/src/10.3/sql/sql_parse.cc:1370
      #23 0x000055bd3b2a2ed6 in do_handle_one_connection (connect=0x55bd3e53b340) at /data/src/10.3/sql/sql_connect.cc:1420
      #24 0x000055bd3b2a2c63 in handle_one_connection (arg=0x55bd3e53b340) at /data/src/10.3/sql/sql_connect.cc:1326
      #25 0x000055bd3b724392 in pfs_spawn_thread (arg=0x55bd3e543a00) at /data/src/10.3/storage/perfschema/pfs.cc:1863
      #26 0x00007efe2a2d8494 in start_thread (arg=0x7efe20200700) at pthread_create.c:333
      #27 0x00007efe286be93f in clone () from /lib/x86_64-linux-gnu/libc.so.6
      

      Long semaphore variation

      All threads from the running server are attached as threads1.

      10.3 c029eae02d5d9

      2017-11-20  0:04:21 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696535160576 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:21 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140697023878912 has waited at btr0sea.ic line 114 for 241.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf57038d30 created in file btr0sea.cc line 260
      a writer (thread id 140697024182016) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      2017-11-20  0:04:21 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696543553280 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:21 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696526767872 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:21 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696535160576 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:21 0 [Note] InnoDB: A semaphore wait:
      --Thread 140697023878912 has waited at btr0sea.ic line 114 for 241.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf57038d30 created in file btr0sea.cc line 260
      a writer (thread id 140697024182016) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      2017-11-20  0:04:21 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696543553280 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:21 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696526767872 has waited at row0purge.cc line 928 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:21 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696770025216 has waited at srv0srv.cc line 2120 for 240.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
       
      =====================================
      2017-11-20 00:04:39 0x7ff6867fc700 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 77 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 1 srv_idle
      srv_master_thread log flush and writes: 1
      ----------
      SEMAPHORES
      ----------
      -------------
      RW-LATCH INFO
      -------------
      RW-LOCK: 0x55cf574ff6d0  Waiters for the lock exist
      Locked: thread 140697023878912 file handler0alter.cc line 9152  X-LOCK
      RW-LOCK: 0x55cf57038d30  Waiters for the lock exist
      Locked: thread 140697024182016 file btr0sea.ic line 96  X-LOCK
      RW-LOCK: 0x55cf57038b60 
      Locked: thread 140697023878912 file btr0sea.ic line 114  X-LOCK
      RW-LOCK: 0x55cf57038990 
      Locked: thread 140697023878912 file btr0sea.ic line 114  X-LOCK
      RW-LOCK: 0x55cf570387c0 
      Locked: thread 140697023878912 file btr0sea.ic line 114  X-LOCK
      RW-LOCK: 0x55cf570385f0 
      Locked: thread 140697023878912 file btr0sea.ic line 114  X-LOCK
      Total number of rw-locks 1079
      OS WAIT ARRAY INFO: reservation count 146
      --Thread 140696535160576 has waited at row0purge.cc line 928 for 259.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      --Thread 140697023878912 has waited at btr0sea.ic line 114 for 259.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf57038d30 created in file btr0sea.cc line 260
      a writer (thread id 140697024182016) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      --Thread 140696543553280 has waited at row0purge.cc line 928 for 259.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      --Thread 140696526767872 has waited at row0purge.cc line 928 for 259.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      --Thread 140696770025216 has waited at srv0srv.cc line 2120 for 258.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      OS WAIT ARRAY INFO: signal count 239
      RW-shared spins 0, rounds 347, OS waits 39
      RW-excl spins 0, rounds 3217, OS waits 40
      RW-sx spins 0, rounds 0, OS waits 0
      Spin rounds per wait: 347.00 RW-shared, 3217.00 RW-excl, 0.00 RW-sx
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 1425
      Purge done for trx's n:o < 1424 undo n:o < 0 state: running
      History list length 19
      Total number of lock structs in row lock hash table 0
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 422172003623128, not started
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422172003622056, not started
      0 lock struct(s), heap size 1160, 0 row lock(s)
      ---TRANSACTION 422172003620984, not started
      mysql tables in use 1, locked 1
      0 lock struct(s), heap size 1160, 0 row lock(s)
      --------
      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
      186 OS file reads, 356 OS file writes, 80 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, 0 merges
      merged operations:
       insert 0, delete mark 0, delete 0
      discarded operations:
       insert 0, delete mark 0, delete 0
      InnoDB: ###### Diagnostic info printed to the standard error stream
      2017-11-20  0:04:52 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696535160576 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140697023878912 has waited at btr0sea.ic line 114 for 272.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf57038d30 created in file btr0sea.cc line 260
      a writer (thread id 140697024182016) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      2017-11-20  0:04:52 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696543553280 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696526767872 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696770025216 has waited at srv0srv.cc line 2120 for 271.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696535160576 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Note] InnoDB: A semaphore wait:
      --Thread 140697023878912 has waited at btr0sea.ic line 114 for 272.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf57038d30 created in file btr0sea.cc line 260
      a writer (thread id 140697024182016) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      2017-11-20  0:04:52 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696543553280 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696526767872 has waited at row0purge.cc line 928 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696770025216 has waited at srv0srv.cc line 2120 for 271.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:04:52 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696795203328 has waited at srv0srv.cc line 1306 for 13.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf570385f0 created in file btr0sea.cc line 260
      a writer (thread id 140697023878912) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file not yet reserved line 0
      Last time write locked in file btr0sea.ic line 114
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
      InnoDB: ###### Diagnostic info printed to the standard error stream
      2017-11-20  0:05:23 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696535160576 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140697023878912 has waited at btr0sea.ic line 114 for 303.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf57038d30 created in file btr0sea.cc line 260
      a writer (thread id 140697024182016) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      2017-11-20  0:05:23 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696543553280 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696526767872 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Warning] InnoDB: A long semaphore wait:
      --Thread 140696770025216 has waited at srv0srv.cc line 2120 for 302.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696535160576 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Note] InnoDB: A semaphore wait:
      --Thread 140697023878912 has waited at btr0sea.ic line 114 for 303.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf57038d30 created in file btr0sea.cc line 260
      a writer (thread id 140697024182016) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file btr0sea.ic line 134
      Last time write locked in file btr0sea.ic line 96
      2017-11-20  0:05:23 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696543553280 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696526767872 has waited at row0purge.cc line 928 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696770025216 has waited at srv0srv.cc line 2120 for 302.00 seconds the semaphore:
      X-lock on RW-latch at 0x55cf574ff6d0 created in file dict0dict.cc line 1109
      a writer (thread id 140697023878912) 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 928
      Last time write locked in file handler0alter.cc line 9152
      2017-11-20  0:05:23 0 [Note] InnoDB: A semaphore wait:
      --Thread 140696795203328 has waited at srv0srv.cc line 1306 for 44.00 seconds the semaphore:
      S-lock on RW-latch at 0x55cf570385f0 created in file btr0sea.cc line 260
      a writer (thread id 140697023878912) has reserved it in mode  exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file not yet reserved line 0
      Last time write locked in file btr0sea.ic line 114
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending reads 0, writes 0
      

      Neither seems to be reproducible on 10.2.

      Attachments

        1. threads
          43 kB
        2. threads1
          36 kB

        Issue Links

          Activity

            elenst, I would suggest that you should include the option loose_innodb_sync_debug in some of your custom tests.

            With that option we come very close to the root cause:

            2018-01-15 11:34:43 14 [ERROR] InnoDB: Thread 140493845485312 already owns a latch BTR_SEARCH at level 16 (SYNC_SEARCH_SYS ), which is at a lower/same level than the requested latch: 24 (SYNC_LOG). RW-LATCH: thread id 140493845485312 addr: 0x60f000003970 Locked from: /mariadb/10.3/storage/innobase/include/btr0sea.ic:96
            

            Apparently, the problem is that the adaptive hash index latch is not being released at this point, like it should have:

            #17 0x0000000001d5b702 in mtr_t::commit (this=0x7fc745bfffe0) at /mariadb/10.3/storage/innobase/mtr/mtr0mtr.cc:572
            #18 0x000000000202f0e4 in row_upd_clust_rec (flags=0, node=0x62000008dbb8, index=0x618000065d08, offsets=0x7fc745c005a0, offsets_heap=0x7fc745c00580, thr=0x62000008deb8, mtr=0x7fc745bfffe0) at /mariadb/10.3/storage/innobase/row/row0upd.cc:2933
            #19 0x000000000202b5f0 in row_upd_clust_step (node=0x62000008dbb8, thr=0x62000008deb8) at /mariadb/10.3/storage/innobase/row/row0upd.cc:3224
            #20 0x000000000202230a in row_upd (node=0x62000008dbb8, thr=0x62000008deb8) at /mariadb/10.3/storage/innobase/row/row0upd.cc:3287
            #21 0x000000000202162f in row_upd_step (thr=0x62000008deb8) at /mariadb/10.3/storage/innobase/row/row0upd.cc:3431
            #22 0x0000000001f05a13 in row_update_for_mysql (prebuilt=0x62000008d108) at /mariadb/10.3/storage/innobase/row/row0mysql.cc:1932
            #23 0x0000000001b12af1 in ha_innobase::update_row (this=0x61d00023d2a0, old_row=0x604000259e78 "\375\002", new_row=0x604000259e70 "\375\006") at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:9149
            

            marko Marko Mäkelä added a comment - elenst , I would suggest that you should include the option loose_innodb_sync_debug in some of your custom tests. With that option we come very close to the root cause: 2018-01-15 11:34:43 14 [ERROR] InnoDB: Thread 140493845485312 already owns a latch BTR_SEARCH at level 16 (SYNC_SEARCH_SYS ), which is at a lower/same level than the requested latch: 24 (SYNC_LOG). RW-LATCH: thread id 140493845485312 addr: 0x60f000003970 Locked from: /mariadb/10.3/storage/innobase/include/btr0sea.ic:96 Apparently, the problem is that the adaptive hash index latch is not being released at this point, like it should have: #17 0x0000000001d5b702 in mtr_t::commit (this=0x7fc745bfffe0) at /mariadb/10.3/storage/innobase/mtr/mtr0mtr.cc:572 #18 0x000000000202f0e4 in row_upd_clust_rec (flags=0, node=0x62000008dbb8, index=0x618000065d08, offsets=0x7fc745c005a0, offsets_heap=0x7fc745c00580, thr=0x62000008deb8, mtr=0x7fc745bfffe0) at /mariadb/10.3/storage/innobase/row/row0upd.cc:2933 #19 0x000000000202b5f0 in row_upd_clust_step (node=0x62000008dbb8, thr=0x62000008deb8) at /mariadb/10.3/storage/innobase/row/row0upd.cc:3224 #20 0x000000000202230a in row_upd (node=0x62000008dbb8, thr=0x62000008deb8) at /mariadb/10.3/storage/innobase/row/row0upd.cc:3287 #21 0x000000000202162f in row_upd_step (thr=0x62000008deb8) at /mariadb/10.3/storage/innobase/row/row0upd.cc:3431 #22 0x0000000001f05a13 in row_update_for_mysql (prebuilt=0x62000008d108) at /mariadb/10.3/storage/innobase/row/row0mysql.cc:1932 #23 0x0000000001b12af1 in ha_innobase::update_row (this=0x61d00023d2a0, old_row=0x604000259e78 "\375\002", new_row=0x604000259e70 "\375\006") at /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:9149

            I suspect that there is some race condition around btr_search_enabled aka innodb_adaptive_hash_index, which the statement

            ALTER TABLE t2 ADD COLUMN v INT AS (i) VIRTUAL;
            

            is disabling behind the scenes. I can repeat the problem with the following, slightly simpler test case:

            --source include/have_innodb.inc
            --connect (con1,localhost,root,,test)
            CREATE TABLE t1 (f INT, KEY(f)) ENGINE=InnoDB;
            INSERT INTO t1 VALUES (),(),(),(),(),(),(),();
            UPDATE t1 SET f = 8;
            UPDATE t1 SET f = 4;
            UPDATE t1 SET f = 6;
            UPDATE t1 SET f = 8;
            UPDATE t1 SET f = 2;
            UPDATE t1 SET f = 9;
            UPDATE t1 SET f = 3;
            UPDATE t1 SET f = 4;
            UPDATE t1 SET f = 6;
            UPDATE t1 SET f = 0;
            UPDATE t1 SET f = 1;
            UPDATE t1 SET f = 5;
            UPDATE t1 SET f = 2;
            --send SET GLOBAL innodb_adaptive_hash_index=OFF;
            --connection default
            UPDATE t1 SET f = 6;
            --connection con1
            --reap
            # Cleanup
            --disconnect con1
            --connection default
            SET GLOBAL innodb_adaptive_hash_index=ON;
            DROP TABLE t1;
            

            I tested MariaDB 10.2 with the same test case. I was expecting it to fail as well, but it passed 4×50 runs of the test with flying colours.

            marko Marko Mäkelä added a comment - I suspect that there is some race condition around btr_search_enabled aka innodb_adaptive_hash_index , which the statement ALTER TABLE t2 ADD COLUMN v INT AS (i) VIRTUAL; is disabling behind the scenes. I can repeat the problem with the following, slightly simpler test case: --source include/have_innodb.inc --connect (con1,localhost,root,,test) CREATE TABLE t1 (f INT , KEY (f)) ENGINE=InnoDB; INSERT INTO t1 VALUES (),(),(),(),(),(),(),(); UPDATE t1 SET f = 8; UPDATE t1 SET f = 4; UPDATE t1 SET f = 6; UPDATE t1 SET f = 8; UPDATE t1 SET f = 2; UPDATE t1 SET f = 9; UPDATE t1 SET f = 3; UPDATE t1 SET f = 4; UPDATE t1 SET f = 6; UPDATE t1 SET f = 0; UPDATE t1 SET f = 1; UPDATE t1 SET f = 5; UPDATE t1 SET f = 2; --send SET GLOBAL innodb_adaptive_hash_index=OFF; --connection default UPDATE t1 SET f = 6; --connection con1 --reap # Cleanup --disconnect con1 --connection default SET GLOBAL innodb_adaptive_hash_index= ON ; DROP TABLE t1; I tested MariaDB 10.2 with the same test case. I was expecting it to fail as well, but it passed 4×50 runs of the test with flying colours.

            I have been suspecting MDEV-11369 Instant ADD COLUMN.
            In row_sel_try_search_shortcut_for_mysql(), if we hit the "default row" pseudo-record, we will advance to the next record. I believe that this is wrong.

            But, this cannot explain the error, because the test case is not using any ADD COLUMN on the table t1.

            marko Marko Mäkelä added a comment - I have been suspecting MDEV-11369 Instant ADD COLUMN. In row_sel_try_search_shortcut_for_mysql() , if we hit the "default row" pseudo-record, we will advance to the next record. I believe that this is wrong. But, this cannot explain the error, because the test case is not using any ADD COLUMN on the table t1.

            The root cause of this bug is that in the function btr_cur_update_in_place() we are skipping this call if the adaptive hash index was disabled during the execution:

            	if (block->index) {
            		btr_search_x_unlock(index);
            

            When debugging the code, I mistook the leaked X lock for a leaked S lock. I did not find any other rw-lock leaks during the MDEV-14952 review/refactoring effort.

            The lock leak was introduced by me in MDEV-12121.

            marko Marko Mäkelä added a comment - The root cause of this bug is that in the function btr_cur_update_in_place() we are skipping this call if the adaptive hash index was disabled during the execution: if (block->index) { btr_search_x_unlock(index); When debugging the code, I mistook the leaked X lock for a leaked S lock. I did not find any other rw-lock leaks during the MDEV-14952 review/refactoring effort. The lock leak was introduced by me in MDEV-12121 .

            People

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

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.