[MDEV-14441] InnoDB hangs when setting innodb_adaptive_hash_index=OFF during UPDATE Created: 2017-11-19  Updated: 2020-05-19  Resolved: 2018-01-15

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.5, 10.3.0
Fix Version/s: 10.3.4, 10.2.13

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: HTML File threads     HTML File threads1    
Issue Links:
Duplicate
is duplicated by MDEV-14625 [Draft] Assertion `!rw_lock_own(btr_g... Closed
Problem/Incident
is caused by MDEV-12121 Introduce build option WITH_INNODB_AH... Closed
Relates
relates to MDEV-13485 MTR tests fail massively with --innod... Closed
relates to MDEV-14952 Avoid repeated calls to btr_get_searc... Closed
relates to MDEV-21936 Assertion `!btr_search_own_any(RW_LOC... Closed
Sub-Tasks:
Key
 Summary
 Type
 Status
 Assignee
MDEV-14955 Add loose_innodb_sync_debug to some ... Technical task Closed Elena Stepanova  

 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.

 Comments   
Comment by Marko Mäkelä [ 2018-01-15 ]

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

Comment by Marko Mäkelä [ 2018-01-15 ]

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.

Comment by Marko Mäkelä [ 2018-01-15 ]

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.

Comment by Marko Mäkelä [ 2018-01-15 ]

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.

Generated at Thu Feb 08 08:13:35 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.