Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.1.3, 10.2.0, 10.3.0, 10.4.0
-
None
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
|
Attachments
Issue Links
- is caused by
-
MDEV-7399 Add support for INFORMATION_SCHEMA.INNODB_MUTEXES
-
- Closed
-
- relates to
-
-
- Closed
-
Activity
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
|
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.
This is possibly a duplicate of MDEV-15798, which was fixed in 10.1.39, 10.2.22, 10.3.13, 10.4.3.
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.
I tried and failed to repeat this with the following:
--source include/have_innodb.inc./mtr --mysqld=--innodb-mutexes --mysqld=--innodb-sync-debug innodb.mdev-18343That 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) \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.