[MDEV-18343] InnoDB: DEADLOCK of threads detected: Mutex RW_LOCK_LIST / Mutex DICT_SYS upon CREATE TABLE .. SELECT * FROM INFORMATION_SCHEMA.`INNODB_MUTEXES` Created: 2019-01-22  Updated: 2020-01-28  Resolved: 2020-01-28

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.1.3, 10.2.0, 10.3.0, 10.4.0
Fix Version/s: 10.4.3, 10.2.22, 10.3.13, 10.1.39

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

Attachments: File mysql.err     File mysql.err.2     File mysql.log     HTML File threads     File threads.2     HTML File threads_full     File threads_full.2    
Issue Links:
Problem/Incident
is caused by MDEV-7399 Add support for INFORMATION_SCHEMA.IN... Closed
Relates
relates to MDEV-15798 Mutex leak on accessing INFORMATION_S... Closed

 Description   

10.4 382115b992

 
DEADLOCK of threads detected!
 
2019-01-22 13:40:02 18 [Note] InnoDB: Mutex 0x557b01794b80 owned by thread 139807583119104 file /home/travis/src/storage/innobase/handler/i_s.cc line 9060
 
--Thread 139809977779968 has waited at sync0rw.cc line 262 for 0.00 seconds the semaphore:
 
Mutex at 0x557b01794b80, Mutex RW_LOCK_LIST created sync0debug.cc:1727, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/handler/i_s.cc line 9060
 
2019-01-22 13:40:02 18 [Note] InnoDB: Mutex 0x557b095274d0 owned by thread 139809977779968 file /home/travis/src/storage/innobase/row/row0mysql.cc line 2330
 
--Thread 139807583119104 has waited at dict0dict.cc line 513 for 0.00 seconds the semaphore:
 
Mutex at 0x557b095274d0, Mutex DICT_SYS created dict0dict.cc:1095, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2330
 
2019-01-22 13:40:02 18 [ERROR] [FATAL] InnoDB: ######################################## Deadlock Detected!
 
190122 13:40:02 [ERROR] mysqld got signal 6 ;


#5  0x00007f28288d902a in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x0000557b006b4113 in ib::fatal::~fatal (this=0x7f277d540660, __in_chrg=<optimized out>) at /home/travis/src/storage/innobase/ut/ut0ut.cc:765
 
#7  0x0000557b0065d767 in sync_array_wait_event (arr=0x557b02838770, cell=@0x7f277d540848: 0x557b028389e0) at /home/travis/src/storage/innobase/sync/sync0arr.cc:462
 
#8  0x0000557b004a8af8 in TTASEventMutex<GenericPolicy>::enter (this=0x557b095274d0, max_spins=60, max_delay=4, filename=0x557b00ddcd68 "/home/travis/src/storage/innobase/dict/dict0dict.cc", line=513) at /home/travis/src/storage/innobase/include/ib0mutex.h:478
 
#9  0x0000557b004a6be5 in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x557b095274d0, n_spins=30, n_delay=4, name=0x557b00ddcd68 "/home/travis/src/storage/innobase/dict/dict0dict.cc", line=513) at /home/travis/src/storage/innobase/include/ib0mutex.h:595
 
#10 0x0000557b00766ef5 in dict_table_close (table=0x7f276c0c3488, dict_locked=0, try_drop=1) at /home/travis/src/storage/innobase/dict/dict0dict.cc:513
 
#11 0x0000557b005edf02 in row_prebuilt_free (prebuilt=0x7f276c1581e8, dict_locked=0) at /home/travis/src/storage/innobase/row/row0mysql.cc:1041
 
#12 0x0000557b00483966 in ha_innobase::close (this=0x7f276c0dfdb8) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:6507
 
#13 0x0000557b002690d2 in handler::ha_close (this=0x7f276c0dfdb8) at /home/travis/src/sql/handler.cc:2786
 
#14 0x0000557b00068545 in closefrm (table=0x7f276c1c8640) at /home/travis/src/sql/table.cc:3609
 
#15 0x0000557b0018dea4 in intern_close_table (table=0x7f276c1c8640) at /home/travis/src/sql/table_cache.cc:222
 
#16 0x0000557b00190da3 in tdc_remove_table (thd=0x7f276c000d10, remove_type=TDC_RT_REMOVE_ALL, db=0x7f276c014048 "transforms", table_name=0x7f276c014058 "insert_select_22992", kill_delayed_threads=false) at /home/travis/src/sql/table_cache.cc:1151
 
#17 0x0000557affeb913c in drop_open_table (thd=0x7f276c000d10, table=0x7f276c1c8640, db_name=0x7f276c0140c8, table_name=0x7f276c0140d8) at /home/travis/src/sql/sql_base.cc:1406
 
#18 0x0000557afff188a3 in select_create::abort_result_set (this=0x7f276c016c40) at /home/travis/src/sql/sql_insert.cc:4755
 
#19 0x0000557afff911a1 in handle_select (thd=0x7f276c000d10, lex=0x7f276c004b20, result=0x7f276c016c40, setup_tables_done_option=0) at /home/travis/src/sql/sql_select.cc:391
 
#20 0x0000557afff527a3 in mysql_execute_command (thd=0x7f276c000d10) at /home/travis/src/sql/sql_parse.cc:4245
 
#21 0x0000557afff5f0bc in mysql_parse (thd=0x7f276c000d10, rawbuf=0x7f276c013d88 "CREATE TABLE transforms.insert_select_22992  SELECT * FROM INFORMATION_SCHEMA.`INNODB_MUTEXES` AS table1 ORDER BY table1.`CREATE_LINE`, table1.`NAME`, table1.`CREATE_LINE`, table1.`OS_WAITS`, table1.`"..., length=292, parser_state=0x7f277d541600, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:8116
 
#22 0x0000557afff4bf07 in dispatch_command (command=COM_QUERY, thd=0x7f276c000d10, packet=0x7f276c00b521 "CREATE TABLE transforms.insert_select_22992  SELECT * FROM INFORMATION_SCHEMA.`INNODB_MUTEXES` AS table1 ORDER BY table1.`CREATE_LINE`, table1.`NAME`, table1.`CREATE_LINE`, table1.`OS_WAITS`, table1.`"..., packet_length=293, is_com_multi=false, is_next_command=false) at /home/travis/src/sql/sql_parse.cc:1852
 
#23 0x0000557afff4a924 in do_command (thd=0x7f276c000d10) at /home/travis/src/sql/sql_parse.cc:1397
 
#24 0x0000557b000b6924 in do_handle_one_connection (connect=0x557b09650600) at /home/travis/src/sql/sql_connect.cc:1402
 
#25 0x0000557b000b6675 in handle_one_connection (arg=0x557b09650600) at /home/travis/src/sql/sql_connect.cc:1308
 
#26 0x0000557b009bea3c in pfs_spawn_thread (arg=0x557b0957fc70) at /home/travis/src/storage/perfschema/pfs.cc:1862
 
#27 0x00007f28295146ba in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#28 0x00007f28289a941d in clone () from /lib/x86_64-linux-gnu/libc.so.6

All threads' stack trace is attached.

It's not reproducible right away, but maybe the stack traces will be enough. If not, please return it to me.

Notes on the origin of the report


https://travis-ci.org/elenst/travis-tests/jobs/482884727
2557 2 1
Tests: elenst-dev 8b68af909d539eb8af1752d1a0e817a6b204d929
Toolbox: b534cb88ebea7d4a116ad03502613d209968d95d

perl ./runall-new.pl --basedir=/home/travis/server --vardir=/home/travis/logs/vardir --duration=350 --threads=6 --seed=1548164361 --short-column-names --reporters=Backtrace,ErrorLog,Deadlock --validators=TransformerNoComparator --transformers=ExecuteAsExecuteImmediate,ExecuteAsInsertSelect,ExecuteAsUpdateDelete --redefine=conf/mariadb/alter_table.yy --redefine=conf/mariadb/instant_add.yy --redefine=conf/mariadb/modules/alter_table_columns.yy --redefine=conf/mariadb/modules/alter_table_indexes.yy --redefine=conf/mariadb/bulk_insert.yy --redefine=conf/mariadb/modules/admin.yy --redefine=conf/mariadb/modules/foreign_keys.yy -redefine=conf/mariadb/modules/locks.yy --redefine=conf/mariadb/modules/sql_mode.yy --redefine=conf/mariadb/redefine_temporary_tables.yy --redefine=conf/mariadb/versioning.yy --redefine=conf/mariadb/sequences.yy --mysqld=--log_output=FILE --mysqld=--max-statement-time=15 --mysqld=--lock-wait-timeout=10 --mysqld=--loose-innodb-lock-wait-timeout=5 --mysqld=--loose-debug_assert_on_not_freed_memory=0 --mysqld=--innodb-buffer-pool-size=2G --grammar=conf/runtime/performance_schema.yy --mysqld=--performance-schema --filter=/home/travis/mariadb-toolbox/travis/10.4-combo-filter.ff --scenario=Restart



 Comments   
Comment by Marko Mäkelä [ 2019-01-23 ]

I tried and failed to repeat this with the following:

--source include/have_innodb.inc
 
CREATE TABLE t1 ENGINE=InnoDB
 
SELECT * FROM INFORMATION_SCHEMA.INNODB_MUTEXES ORDER BY CREATE_LINE;
 
SHOW CREATE TABLE t1;
 
DROP TABLE t1;


./mtr --mysqld=--innodb-mutexes --mysqld=--innodb-sync-debug innodb.mdev-18343

That said, code review suggests that the bug is very possible. The key could be the ORDER BY or some buffering which can cause calls to Field::store() or similar to fail.
The function i_s_innodb_mutexes_fill_table() is wrapping some calls in the following macro:

#define OK(expr)		\
 
	if ((expr) != 0) {	\
 
		DBUG_RETURN(1);	\
 
	}

If this macro causes a return from i_s_innodb_mutexes_fill_table(), then a call to mutex_exit(&rw_lock_list_mutex) would be skipped.
The broken code was introduced in MariaDB 10.1.3.

The function sync_arr_fill_sys_semphore_waits_table that was added at the same time to implement INFORMATION_SCHEMA.INNODB_SEMAPHORE_WAITS does not appear to suffer from a deadlock, but instead it appears to suffer from race conditions, because the access to the global data structure is not being protected by anything.

Comment by Elena Stepanova [ 2019-01-29 ]

Here is another variation, hopefully the same problem. This one happened on server shutdown.

10.4 c231829

 
2019-01-28 21:24:38 0 [Note] /home/travis/server/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
 
2019-01-28 21:24:38 0 [Note] Event Scheduler: Purging the queue. 14 events
 
########################################
 
DEADLOCK of threads detected!
 
2019-01-28 21:24:38 17 [Note] InnoDB: Mutex 0x55c35e390640 owned by thread 140554282407680 file /home/travis/src/storage/innobase/handler/i_s.cc line 9060
 
--Thread 140554282710784 has waited at sync0rw.cc line 262 for 0.00 seconds the semaphore:
 
Mutex at 0x55c35e390640, Mutex RW_LOCK_LIST created sync0debug.cc:1727, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/handler/i_s.cc line 9060
 
2019-01-28 21:24:38 17 [Note] InnoDB: Mutex 0x55c366469e50 owned by thread 140554282710784 file /home/travis/src/storage/innobase/row/row0mysql.cc line 2330
 
--Thread 140554282407680 has waited at dict0dict.cc line 513 for 0.00 seconds the semaphore:
 
Mutex at 0x55c366469e50, Mutex DICT_SYS created dict0dict.cc:1095, lock var 2
 
Last time reserved in file /home/travis/src/storage/innobase/row/row0mysql.cc line 2330
 
2019-01-28 21:24:38 17 [ERROR] [FATAL] InnoDB: ######################################## Deadlock Detected!
 
190128 21:24:38 [ERROR] mysqld got signal 6 ;
 
 
 
#5  0x00007fd559f1602a in abort () from /lib/x86_64-linux-gnu/libc.so.6
 
#6  0x000055c35d2612ab in ib::fatal::~fatal (this=0x7fd558130830, __in_chrg=<optimized out>) at /home/travis/src/storage/innobase/ut/ut0ut.cc:765
 
#7  0x000055c35d20a887 in sync_array_wait_event (arr=0x55c35f77b350, cell=@0x7fd558130a18: 0x55c35f77b600) at /home/travis/src/storage/innobase/sync/sync0arr.cc:462
 
#8  0x000055c35d055a16 in TTASEventMutex<GenericPolicy>::enter (this=0x55c366469e50, max_spins=60, max_delay=4, filename=0x55c35d9b3308 "/home/travis/src/storage/innobase/dict/dict0dict.cc", line=513) at /home/travis/src/storage/innobase/include/ib0mutex.h:478
 
#9  0x000055c35d053bed in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55c366469e50, n_spins=30, n_delay=4, name=0x55c35d9b3308 "/home/travis/src/storage/innobase/dict/dict0dict.cc", line=513) at /home/travis/src/storage/innobase/include/ib0mutex.h:595
 
#10 0x000055c35d3140ba in dict_table_close (table=0x7fd4903db6d8, dict_locked=0, try_drop=1) at /home/travis/src/storage/innobase/dict/dict0dict.cc:513
 
#11 0x000055c35d19aeb4 in row_prebuilt_free (prebuilt=0x7fd490070628, dict_locked=0) at /home/travis/src/storage/innobase/row/row0mysql.cc:1041
 
#12 0x000055c35d0306ba in ha_innobase::close (this=0x7fd49008d798) at /home/travis/src/storage/innobase/handler/ha_innodb.cc:6504
 
#13 0x000055c35ce095ea in handler::ha_close (this=0x7fd49008d798) at /home/travis/src/sql/handler.cc:2960
 
#14 0x000055c35cbeb6f5 in closefrm (table=0x7fd49007c870) at /home/travis/src/sql/table.cc:3620
 
#15 0x000055c35cd334c4 in THD::close_temporary_table (this=0x7fd490000c70, table=0x7fd49007c870) at /home/travis/src/sql/temporary_tables.cc:1226
 
#16 0x000055c35cd3400f in THD::free_temporary_table (this=0x7fd490000c70, table=0x7fd49007c870) at /home/travis/src/sql/temporary_tables.cc:1469
 
#17 0x000055c35cd31c70 in THD::close_temporary_tables (this=0x7fd490000c70) at /home/travis/src/sql/temporary_tables.cc:507
 
#18 0x000055c35ca61cc5 in THD::cleanup (this=0x7fd490000c70) at /home/travis/src/sql/sql_class.cc:1515
 
#19 0x000055c35c9a0255 in unlink_thd (thd=0x7fd490000c70) at /home/travis/src/sql/mysqld.cc:2752
 
#20 0x000055c35c9a073b in one_thread_per_connection_end (thd=0x7fd490000c70, put_in_cache=true) at /home/travis/src/sql/mysqld.cc:2902
 
#21 0x000055c35cc3a518 in do_handle_one_connection (connect=0x55c3665e8ce0) at /home/travis/src/sql/sql_connect.cc:1413
 
#22 0x000055c35cc3a1db in handle_one_connection (arg=0x55c3665e8ce0) at /home/travis/src/sql/sql_connect.cc:1301
 
#23 0x00007fd55ad556ba in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#24 0x00007fd559fe641d in clone () from /lib/x86_64-linux-gnu/libc.so.6

mysql.err.2 threads.2 threads_full.2

Comment by Marko Mäkelä [ 2019-02-05 ]

threads_full.2 suggests that multiple threads are waiting for dict_operation_lock or dict_sys->mutex. Thread 28 appears to be holding these both exclusively while waiting for rw_lock_list_mutex in rw_lock_free_func() during DROP TABLE. It is indeed possible that rw_lock_list_mutex was never released due to this bug.

Comment by Marko Mäkelä [ 2019-08-12 ]

This is possibly a duplicate of MDEV-15798, which was fixed in 10.1.39, 10.2.22, 10.3.13, 10.4.3.

Comment by Marko Mäkelä [ 2020-01-28 ]

I think that this is rather obviously a deadlock of MDEV-15798.

I tried again, and finally figured out how to make the schema_table_store_record() fail:

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (a SERIAL) ENGINE=InnoDB;
 
 
 
SET DEBUG_DBUG='+d,maria_pretend_crashed_table_on_usage';
 
--error ER_NOT_KEYFILE
 
SELECT * FROM INFORMATION_SCHEMA.INNODB_MUTEXES ORDER BY 1 DESC;
 
 
 
DROP TABLE t1;

invoked as

./mtr --mysqld=--innodb-mutexes innodb.mdev-18343

with the following patch to reintroduce MDEV-15798 and to ensure that there will be output:

diff --git a/storage/innobase/handler/i_s.cc b/storage/innobase/handler/i_s.cc
 
index 5fe2307e8ac..b88287c5210 100644
 
--- a/storage/innobase/handler/i_s.cc
 
+++ b/storage/innobase/handler/i_s.cc
 
@@ -7637,18 +7637,9 @@ i_s_innodb_mutexes_fill_table(
 
 #endif /* JAN_TODO_FIXME */
 
 
 	{
 
-		struct Locking
 
-		{
 
-			Locking() { mutex_enter(&rw_lock_list_mutex); }
 
-			~Locking() { mutex_exit(&rw_lock_list_mutex); }
 
-		} locking;
 
-
 
+		mutex_enter(&rw_lock_list_mutex);
 
 		for (lock = UT_LIST_GET_FIRST(rw_lock_list); lock != NULL;
 
 		     lock = UT_LIST_GET_NEXT(list, lock)) {
 
-			if (lock->count_os_wait == 0) {
 
-				continue;
 
-			}
 
-
 
 			if (buf_pool_is_block_lock(lock)) {
 
 				block_lock = lock;
 
 				block_lock_oswait_count += lock->count_os_wait;
 
@@ -7687,6 +7678,7 @@ i_s_innodb_mutexes_fill_table(
 
 			fields[MUTEXES_OS_WAITS]->set_notnull();
 
 			OK(schema_table_store_record(thd, tables->table));
 
 		}
 
+		mutex_exit(&rw_lock_list_mutex);
 
 	}
 
 
 	DBUG_RETURN(0);

It will crash the debug build:

10.5ish

 
Version: '10.5.1-MariaDB-debug-log'  socket: '/dev/shm/10.5-MDEV-12353/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
 
2020-01-28 22:04:08 4 [ERROR] mysqld: Index for table '(temporary)' is corrupt; try to repair it
 
mysqld: /mariadb/10.5-MDEV-12353/storage/innobase/include/sync0policy.h:121: void MutexDebug<TTASEventMutex<GenericPolicy> >::enter(const Mutex &, const char *, unsigned int) [Mutex = TTASEventMutex<GenericPolicy>]: Assertion `!is_owned()' failed.

With the minimal patch (to only ensure that there will be output), there is no crash:

diff --git a/storage/innobase/handler/i_s.cc b/storage/innobase/handler/i_s.cc
 
index 5fe2307e8ac..da04a1e5df1 100644
 
--- a/storage/innobase/handler/i_s.cc
 
+++ b/storage/innobase/handler/i_s.cc
 
@@ -7645,10 +7645,6 @@ i_s_innodb_mutexes_fill_table(
 
 
 		for (lock = UT_LIST_GET_FIRST(rw_lock_list); lock != NULL;
 
 		     lock = UT_LIST_GET_NEXT(list, lock)) {
 
-			if (lock->count_os_wait == 0) {
 
-				continue;
 
-			}
 
-
 
 			if (buf_pool_is_block_lock(lock)) {
 
 				block_lock = lock;
 
 				block_lock_oswait_count += lock->count_os_wait;

Without this patch, the CREATE…SELECT would succeed despite the fault injection, because ha_maria::write_row() would not be called.

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