[MDEV-24876] InnoDB: Failing assertion: lock->lock_word == X_LOCK_DECR or safe_mutex: Trying to destroy a mutex cache->lock that was locked - Jira

Details

Type: Bug
Status: Stalled (View Workflow)
Priority: Major
Resolution: Unresolved
Affects Version/s: 10.2(EOL), (13)
10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11, 11.0(EOL), 11.1(EOL), 11.2(EOL), 11.3(EOL)
Fix Version/s: 10.5, 10.6, 10.11
Component/s: Full-text Search, Locking, Storage Engine - InnoDB
Labels:
- crash
- foreign-keys
- race

Description

The test case is non-deterministic, run with --repeat=N. It currently fails fairly well for me, within 10 attempts or less.
The test case is for reproducing purposes only. I hope it could be turned into a deterministic synchronized one when the problem is clear.

--source include/have_innodb.inc

--source include/have_sequence.inc

call mtr.add_suppression("has or is referenced in foreign key constraints");

SET @stats= @@innodb_stats_persistent;

SET GLOBAL innodb_stats_persistent= ON;

CREATE TABLE t1 (pk INT PRIMARY KEY, a INT, KEY (a)) ENGINE=InnoDB;

INSERT INTO t1 (pk) SELECT seq FROM seq_1_to_100;

CREATE TABLE t2 (

  pk INT PRIMARY KEY,

  b INT,

  c VARCHAR(8),

  KEY (b),

  FULLTEXT KEY (c),

  FOREIGN KEY (pk) REFERENCES t1 (pk),

  FOREIGN KEY (b) REFERENCES t1 (a)

) ENGINE=InnoDB;

FLUSH TABLES;

--connect (con1,localhost,root,,test)

SET FOREIGN_KEY_CHECKS= OFF;

ALTER TABLE t2 DROP KEY b;

SET FOREIGN_KEY_CHECKS= ON;

--send

  ALTER TABLE t2 FORCE, ALGORITHM=COPY;

--connection default

--let $run= 20

while ($run)

  DELETE FROM t1 ORDER BY a LIMIT 5;

  --dec $run

# Cleanup

--connection con1

--error ER_ERROR_ON_RENAME

--reap

--disconnect con1

--connection default

DROP TABLE t2, t1;

SET GLOBAL innodb_stats_persistent= @stats;

Assertion failure on 10.2-10.5 (scroll the code block for the 2nd conflicting thread):

10.2 da3211e4
2021-02-15 21:55:50 140664529213184 [ERROR] InnoDB: In ALTER TABLE `test`.`t2` has or is referenced in foreign key constraints which are not compatible with the new table definition.
2021-02-15 21:55:50 140664529213184 [Note] InnoDB: Deferring DROP TABLE `test`.`FTS_0000000000000020_CONFIG`; renaming to test/#sql-ib35
2021-02-15 21:55:50 0x7fef034bd700 InnoDB: Assertion failure in file /data/src/10.2/storage/innobase/sync/sync0rw.cc line 259
InnoDB: Failing assertion: lock->lock_word == X_LOCK_DECR

#6 0x000055e2dcc5d75c in ut_dbg_assertion_failed (expr=0x55e2dd1f7c30 "lock->lock_word == X_LOCK_DECR", file=0x55e2dd1f7b30 "/data/src/10.2/storage/innobase/sync/sync0rw.cc", line=259) at /data/src/10.2/storage/innobase/ut/ut0dbg.cc:60
#7 0x000055e2dcc09f61 in rw_lock_free_func (lock=0x7feeb40332c0) at /data/src/10.2/storage/innobase/sync/sync0rw.cc:259
#8 0x000055e2dcd734a3 in pfs_rw_lock_free_func (lock=0x7feeb40332c0) at /data/src/10.2/storage/innobase/include/sync0rw.ic:603
#9 0x000055e2dcd77092 in fts_cache_destroy (cache=0x7feeb40332c0) at /data/src/10.2/storage/innobase/fts/fts0fts.cc:287
#10 0x000055e2dcd8197f in fts_t::~fts_t (this=0x7feeb4037180, __in_chrg=<optimized out>) at /data/src/10.2/storage/innobase/fts/fts0fts.cc:5383
#11 0x000055e2dcd81a57 in fts_free (table=0x7feeb4032730) at /data/src/10.2/storage/innobase/fts/fts0fts.cc:5420
#12 0x000055e2dcb96468 in row_drop_ancillary_fts_tables (table=0x7feeb4032730, trx=0x7fef08123330) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3197
#13 0x000055e2dcb97897 in row_drop_table_for_mysql (name=0x7fef034b84d0 "test/#sql-f2425_a", trx=0x7fef08123330, sqlcom=SQLCOM_ALTER_TABLE, create_failed=false, nonatomic=true) at /data/src/10.2/storage/innobase/row/row0mysql.cc:3707
#14 0x000055e2dca71ec7 in ha_innobase::delete_table (this=0x7feeb4015f80, name=0x7fef034b9cc0 "./test/#sql-f2425_a", sqlcom=SQLCOM_ALTER_TABLE) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13317
#15 0x000055e2dca5bfac in ha_innobase::delete_table (this=0x7feeb4015f80, name=0x7fef034b9cc0 "./test/#sql-f2425_a") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:13442
#16 0x000055e2dc84fc70 in handler::ha_delete_table (this=0x7feeb4015f80, name=0x7fef034b9cc0 "./test/#sql-f2425_a") at /data/src/10.2/sql/handler.cc:4481
#17 0x000055e2dc84a1ed in ha_delete_table (thd=0x7feeb4000d90, table_type=0x55e2de690380, path=0x7fef034b9cc0 "./test/#sql-f2425_a", db=0x7feeb4013c00 "test", alias=0x7fef034ba6b0 "#sql-f2425_a", generate_warning=false) at /data/src/10.2/sql/handler.cc:2443
#18 0x000055e2dc68ac51 in quick_rm_table (thd=0x7feeb4000d90, base=0x55e2de690380, db=0x7feeb4013c00 "test", table_name=0x7fef034ba6b0 "#sql-f2425_a", flags=3, table_path=0x0) at /data/src/10.2/sql/sql_table.cc:2734
#19 0x000055e2dc69e202 in mysql_alter_table (thd=0x7feeb4000d90, new_db=0x7feeb4013c00 "test", new_name=0x0, create_info=0x7fef034bb290, table_list=0x7feeb40135e8, alter_info=0x7fef034bb1e0, order_num=0, order=0x0, ignore=false) at /data/src/10.2/sql/sql_table.cc:9847
#20 0x000055e2dc71bec4 in Sql_cmd_alter_table::execute (this=0x7feeb4013c10, thd=0x7feeb4000d90) at /data/src/10.2/sql/sql_alter.cc:333
#21 0x000055e2dc5ca079 in mysql_execute_command (thd=0x7feeb4000d90) at /data/src/10.2/sql/sql_parse.cc:5994
#22 0x000055e2dc5cf091 in mysql_parse (thd=0x7feeb4000d90, rawbuf=0x7feeb40134f8 "ALTER TABLE t2 FORCE, ALGORITHM=COPY", length=36, parser_state=0x7fef034bc5f0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7763
#23 0x000055e2dc5bd36a in dispatch_command (command=COM_QUERY, thd=0x7feeb4000d90, packet=0x7feeb4008b51 "", packet_length=36, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1827
#24 0x000055e2dc5bbe65 in do_command (thd=0x7feeb4000d90) at /data/src/10.2/sql/sql_parse.cc:1381
#25 0x000055e2dc7168ba in do_handle_one_connection (connect=0x55e2dec36b20) at /data/src/10.2/sql/sql_connect.cc:1336
#26 0x000055e2dc71661f in handle_one_connection (arg=0x55e2dec36b20) at /data/src/10.2/sql/sql_connect.cc:1241
#27 0x000055e2dcf3ed22 in pfs_spawn_thread (arg=0x55e2dec36df0) at /data/src/10.2/storage/perfschema/pfs.cc:1869
#28 0x00007fef0d5f8609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#29 0x00007fef0d1d4293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 27 (Thread 0x7fef03508700 (LWP 992322)):
#0 futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55e2de879ff8) at ../sysdeps/nptl/futex-internal.h:183
#1 __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x55e2de879fa8, cond=0x55e2de879fd0) at pthread_cond_wait.c:508
#2 __pthread_cond_wait (cond=0x55e2de879fd0, mutex=0x55e2de879fa8) at pthread_cond_wait.c:638
#3 0x000055e2dcb12d5c in os_event::wait (this=0x55e2de879f90) at /data/src/10.2/storage/innobase/os/os0event.cc:158
#4 0x000055e2dcb1280c in os_event::wait_low (this=0x55e2de879f90, reset_sig_count=7) at /data/src/10.2/storage/innobase/os/os0event.cc:325
#5 0x000055e2dcb12b26 in os_event_wait_low (event=0x55e2de879f90, reset_sig_count=7) at /data/src/10.2/storage/innobase/os/os0event.cc:507
#6 0x000055e2dcc0736b in sync_array_wait_event (arr=0x55e2de6b9330, cell=@0x7fef035059e0: 0x7fef08521050) at /data/src/10.2/storage/innobase/sync/sync0arr.cc:471
#7 0x000055e2dca75187 in TTASEventMutex<GenericPolicy>::enter (this=0x55e2de879e80, max_spins=60, max_delay=4, filename=0x55e2dd275178 "/data/src/10.2/storage/innobase/fts/fts0fts.cc", line=927) at /data/src/10.2/storage/innobase/include/ib0mutex.h:516
#8 0x000055e2dca732a9 in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55e2de879e80, n_spins=30, n_delay=4, name=0x55e2dd275178 "/data/src/10.2/storage/innobase/fts/fts0fts.cc", line=927) at /data/src/10.2/storage/innobase/include/ib0mutex.h:637
#9 0x000055e2dcd7872e in fts_que_graph_free_check_lock (fts_table=0x7fef03505b00, index_cache=0x0, graph=0x7feeb006b6b0) at /data/src/10.2/storage/innobase/fts/fts0fts.cc:927
#10 0x000055e2dcd7bb77 in fts_cmp_set_sync_doc_id (table=0x7feeb4032730, cmp_doc_id=0, read_only=1, doc_id=0x7fef03505f88) at /data/src/10.2/storage/innobase/fts/fts0fts.cc:2679
#11 0x000055e2dcd83b8e in fts_init_index (table=0x7feeb4032730, has_cache_lock=1) at /data/src/10.2/storage/innobase/fts/fts0fts.cc:6344
#12 0x000055e2dcd80a9b in fts_init_doc_id (table=0x7feeb4032730) at /data/src/10.2/storage/innobase/fts/fts0fts.cc:4867
#13 0x000055e2dcb9311f in init_fts_doc_id_for_ref (table=0x7feeb0173370, depth=0x7fef03506050) at /data/src/10.2/storage/innobase/row/row0mysql.cc:1723
#14 0x000055e2dcb93364 in row_update_for_mysql (prebuilt=0x7feeb00a47c0) at /data/src/10.2/storage/innobase/row/row0mysql.cc:1772
#15 0x000055e2dca53f47 in ha_innobase::delete_row (this=0x7feeb00a0258, record=0x7feeb012aaf0 "\377\017") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9061
#16 0x000055e2dc8544ce in handler::ha_delete_row (this=0x7feeb00a0258, buf=0x7feeb012aaf0 "\377\017") at /data/src/10.2/sql/handler.cc:6178
#17 0x000055e2dc9d8f61 in mysql_delete (thd=0x7feeb0000d90, table_list=0x7feeb00127e0, conds=0x0, order_list=0x7feeb0005328, limit=1, options=0, result=0x0) at /data/src/10.2/sql/sql_delete.cc:583
#18 0x000055e2dc5c45a9 in mysql_execute_command (thd=0x7feeb0000d90) at /data/src/10.2/sql/sql_parse.cc:4397
#19 0x000055e2dc5cf091 in mysql_parse (thd=0x7feeb0000d90, rawbuf=0x7feeb00126f8 "DELETE FROM t1 ORDER BY a LIMIT 5", length=33, parser_state=0x7fef035075f0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7763
#20 0x000055e2dc5bd36a in dispatch_command (command=COM_QUERY, thd=0x7feeb0000d90, packet=0x7feeb0008b51 "DELETE FROM t1 ORDER BY a LIMIT 5", packet_length=33, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1827
#21 0x000055e2dc5bbe65 in do_command (thd=0x7feeb0000d90) at /data/src/10.2/sql/sql_parse.cc:1381
#22 0x000055e2dc7168ba in do_handle_one_connection (connect=0x55e2debdd450) at /data/src/10.2/sql/sql_connect.cc:1336
#23 0x000055e2dc71661f in handle_one_connection (arg=0x55e2debdd450) at /data/src/10.2/sql/sql_connect.cc:1241
#24 0x000055e2dcf3ed22 in pfs_spawn_thread (arg=0x55e2debc0840) at /data/src/10.2/storage/perfschema/pfs.cc:1869
#25 0x00007fef0d5f8609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#26 0x00007fef0d1d4293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

On 10.6 (scroll the code block for the 2nd conflicting thread):

10.6 a1542f8a
2021-02-16 2:10:04 5 [ERROR] InnoDB: In ALTER TABLE `test`.`t2` has or is referenced in foreign key constraints which are not compatible with the new table definition.
2021-02-16 2:10:04 5 [Warning] InnoDB: In ALTER TABLE `test`.`t2` has or is referenced in foreign key constraints which are not compatible with the new table definition.
CURRENT_TEST: bug.mutex2
2021-02-16 2:10:05 10 [ERROR] InnoDB: In ALTER TABLE `test`.`t2` has or is referenced in foreign key constraints which are not compatible with the new table definition.
2021-02-16 2:10:05 10 [Note] InnoDB: Deferring DROP TABLE `test`.`FTS_0000000000000038_CONFIG`; renaming to test/#sql-ib59
safe_mutex: Trying to destroy a mutex cache->lock that was locked at /data/src/10.6/storage/innobase/fts/fts0fts.cc, line 4785 at /data/src/10.6/storage/innobase/fts/fts0fts.cc, line 294
210216 2:10:05 [ERROR] mysqld got signal 6 ;

#5 0x00007efcf3802859 in __GI_abort () at abort.c:79
#6 0x000056145aa6d0b4 in safe_mutex_destroy (mp=0x7efcb006e4e8, file=0x56145af975e8 "/data/src/10.6/storage/innobase/fts/fts0fts.cc", line=294) at /data/src/10.6/mysys/thr_mutex.c:600
#7 0x000056145a95b40e in inline_mysql_mutex_destroy (that=0x7efcb006e4e8, src_file=0x56145af975e8 "/data/src/10.6/storage/innobase/fts/fts0fts.cc", src_line=294) at /data/src/10.6/include/mysql/psi/mysql_thread.h:724
#8 0x000056145a95fcee in fts_cache_destroy (cache=0x7efcb006e4e8) at /data/src/10.6/storage/innobase/fts/fts0fts.cc:294
#9 0x000056145a96b047 in fts_t::~fts_t (this=0x7efcb005c4c8, __in_chrg=<optimized out>) at /data/src/10.6/storage/innobase/fts/fts0fts.cc:5284
#10 0x000056145a96b11f in fts_free (table=0x7efcb005f898) at /data/src/10.6/storage/innobase/fts/fts0fts.cc:5321
#11 0x000056145a77022a in row_drop_ancillary_fts_tables (table=0x7efcb005f898, trx=0x7efcede683d8) at /data/src/10.6/storage/innobase/row/row0mysql.cc:3201
#12 0x000056145a77139e in row_drop_table_for_mysql (name=0x7efcecb6c440 "test/#sql-alter-fcbe8-a", trx=0x7efcede683d8, sqlcom=SQLCOM_ALTER_TABLE, create_failed=false, nonatomic=true) at /data/src/10.6/storage/innobase/row/row0mysql.cc:3630
#13 0x000056145a5e18d2 in ha_innobase::delete_table (this=0x7efcb0017d08, name=0x7efcecb6d540 "./test/#sql-alter-fcbe8-a", sqlcom=SQLCOM_ALTER_TABLE) at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:13012
#14 0x000056145a5c8628 in ha_innobase::delete_table (this=0x7efcb0017d08, name=0x7efcecb6d540 "./test/#sql-alter-fcbe8-a") at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:13139
#15 0x000056145a13b7e3 in hton_drop_table (hton=0x56145d39cf48, path=0x7efcecb6d540 "./test/#sql-alter-fcbe8-a") at /data/src/10.6/sql/handler.cc:564
#16 0x000056145a140f0f in ha_delete_table (thd=0x7efcb0000db8, hton=0x56145d39cf48, path=0x7efcecb6d540 "./test/#sql-alter-fcbe8-a", db=0x7efcecb6e8b0, alias=0x7efcecb6e8e0, generate_warning=false) at /data/src/10.6/sql/handler.cc:2770
#17 0x0000561459ec3c61 in quick_rm_table (thd=0x7efcb0000db8, base=0x56145d39cf48, db=0x7efcecb6e8b0, table_name=0x7efcecb6e8e0, flags=3, table_path=0x0) at /data/src/10.6/sql/sql_table.cc:2915
#18 0x0000561459edb960 in mysql_alter_table (thd=0x7efcb0000db8, new_db=0x7efcb0005830, new_name=0x7efcb0005c30, create_info=0x7efcecb6f480, table_list=0x7efcb0014f90, alter_info=0x7efcecb6f3b0, order_num=0, order=0x0, ignore=false, if_exists=false) at /data/src/10.6/sql/sql_table.cc:11002
#19 0x0000561459f82d54 in Sql_cmd_alter_table::execute (this=0x7efcb0015670, thd=0x7efcb0000db8) at /data/src/10.6/sql/sql_alter.cc:539
#20 0x0000561459dd9683 in mysql_execute_command (thd=0x7efcb0000db8) at /data/src/10.6/sql/sql_parse.cc:5880
#21 0x0000561459ddf9ee in mysql_parse (thd=0x7efcb0000db8, rawbuf=0x7efcb0014ea0 "ALTER TABLE t2 FORCE, ALGORITHM=COPY", length=36, parser_state=0x7efcecb70510) at /data/src/10.6/sql/sql_parse.cc:7906
#22 0x0000561459dcbf31 in dispatch_command (command=COM_QUERY, thd=0x7efcb0000db8, packet=0x7efcb0008e49 "", packet_length=36) at /data/src/10.6/sql/sql_parse.cc:1833
#23 0x0000561459dca948 in do_command (thd=0x7efcb0000db8) at /data/src/10.6/sql/sql_parse.cc:1365
#24 0x0000561459f78117 in do_handle_one_connection (connect=0x56145d83d048, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
#25 0x0000561459f77e7a in handle_one_connection (arg=0x56145d38b8f8) at /data/src/10.6/sql/sql_connect.cc:1312
#26 0x000056145a4d5e97 in pfs_spawn_thread (arg=0x56145d2bbdd8) at /data/src/10.6/storage/perfschema/pfs.cc:2201
#27 0x00007efcf3d2b609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#28 0x00007efcf38ff293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Thread 12 (Thread 0x7efcecbbc700 (LWP 1035255)):
#0 __lll_lock_wait (futex=futex@entry=0x56145b544440 <dict_sys+128>, private=0) at lowlevellock.c:52
#1 0x00007efcf3d2e0a3 in __GI___pthread_mutex_lock (mutex=0x56145b544440 <dict_sys+128>) at ../nptl/pthread_mutex_lock.c:80
#2 0x000056145aa6c0fe in safe_mutex_lock (mp=0x56145b544418 <dict_sys+88>, my_flags=0, file=0x56145af70620 "/data/src/10.6/storage/innobase/dict/dict0dict.cc", line=1077) at /data/src/10.6/mysys/thr_mutex.c:290
#3 0x000056145a8def13 in inline_mysql_mutex_lock (that=0x56145b544418 <dict_sys+88>, src_file=0x56145af70620 "/data/src/10.6/storage/innobase/dict/dict0dict.cc", src_line=1077) at /data/src/10.6/include/mysql/psi/mysql_thread.h:750
#4 0x000056145a8e5202 in dict_sys_t::mutex_lock_wait (this=0x56145b5443c0 <dict_sys>) at /data/src/10.6/storage/innobase/dict/dict0dict.cc:1077
#5 0x000056145a8e54b9 in dict_sys_t::mutex_lock (this=0x56145b5443c0 <dict_sys>) at /data/src/10.6/storage/innobase/dict/dict0dict.cc:1101
#6 0x000056145a96149e in fts_que_graph_free_check_lock (fts_table=0x7efcecbb9db0, index_cache=0x0, graph=0x7efcb8067a48) at /data/src/10.6/storage/innobase/fts/fts0fts.cc:915
#7 0x000056145a964e27 in fts_cmp_set_sync_doc_id (table=0x7efcb005f898, cmp_doc_id=0, read_only=0, doc_id=0x7efcecbba238) at /data/src/10.6/storage/innobase/fts/fts0fts.cc:2640
#8 0x000056145a96a160 in fts_init_doc_id (table=0x7efcb005f898) at /data/src/10.6/storage/innobase/fts/fts0fts.cc:4797
#9 0x000056145a76bfc0 in init_fts_doc_id_for_ref (table=0x7efcb8b3eb78, depth=0x7efcecbba2b0) at /data/src/10.6/storage/innobase/row/row0mysql.cc:1693
#10 0x000056145a76c298 in row_update_for_mysql (prebuilt=0x7efcb8bac2a8) at /data/src/10.6/storage/innobase/row/row0mysql.cc:1742
#11 0x000056145a5be16b in ha_innobase::delete_row (this=0x7efcb8116b10, record=0x7efcb8ca0128 "\377\b") at /data/src/10.6/storage/innobase/handler/ha_innodb.cc:8267
#12 0x000056145a15126f in handler::ha_delete_row (this=0x7efcb8116b10, buf=0x7efcb8ca0128 "\377\b") at /data/src/10.6/sql/handler.cc:7269
#13 0x000056145a32e0d9 in TABLE::delete_row (this=0x7efcb82063f8) at /data/src/10.6/sql/sql_delete.cc:280
#14 0x000056145a32ae87 in mysql_delete (thd=0x7efcb8000db8, table_list=0x7efcb8013db8, conds=0x0, order_list=0x7efcb8005a28, limit=3, options=0, result=0x0) at /data/src/10.6/sql/sql_delete.cc:815
#15 0x0000561459dd4d65 in mysql_execute_command (thd=0x7efcb8000db8) at /data/src/10.6/sql/sql_parse.cc:4695
#16 0x0000561459ddf9ee in mysql_parse (thd=0x7efcb8000db8, rawbuf=0x7efcb8013cd0 "DELETE FROM t1 ORDER BY a LIMIT 5", length=33, parser_state=0x7efcecbbb510) at /data/src/10.6/sql/sql_parse.cc:7906
#17 0x0000561459dcbf31 in dispatch_command (command=COM_QUERY, thd=0x7efcb8000db8, packet=0x7efcb80440e9 "DELETE FROM t1 ORDER BY a LIMIT 5", packet_length=33) at /data/src/10.6/sql/sql_parse.cc:1833
#18 0x0000561459dca948 in do_command (thd=0x7efcb8000db8) at /data/src/10.6/sql/sql_parse.cc:1365
#19 0x0000561459f78117 in do_handle_one_connection (connect=0x56145d867028, put_in_cache=true) at /data/src/10.6/sql/sql_connect.cc:1410
#20 0x0000561459f77e7a in handle_one_connection (arg=0x56145d84f7a8) at /data/src/10.6/sql/sql_connect.cc:1312
#21 0x000056145a4d5e97 in pfs_spawn_thread (arg=0x56145d8cb688) at /data/src/10.6/storage/perfschema/pfs.cc:2201
#22 0x00007efcf3d2b609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#23 0x00007efcf38ff293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The 10.2 version of the failure may be related to ~~MDEV-24076~~, it's hard to say for sure from what buildbot returned in there.

Also, the failure happens interchangeably with MDEV-18421. I don't know if it's the same bug (same root cause), or a separate problem revealed by the same scenario.
On a non-debug version I am getting MDEV-18421.

Attachments

Issue Links

relates to

MDEV-18421 Server crash or assertion `foreign->foreign_table != __null' failed in init_fts_doc_id_for_ref

Stalled

MDEV-24076 innodb_zip.create_options failed in buildbot: InnoDB: Failing assertion: lock->lock_word == X_LOCK_DECR

Closed

Activity

Ascending order - Click to sort in descending order

Marko Mäkelä added a comment - 2023-11-29 12:12

The test case reproduces a different crash on a recent 10.6:

10.6 ba6bf7ad9e52c1dc31a22a619c17e1bb55b46d5d
mysqltest: At line 36: query 'DELETE FROM t1 ORDER BY a LIMIT 5' failed: <Unknown> (2013): Lost connection to server during query
…
mariadbd: /mariadb/10.6/storage/innobase/row/row0mysql.cc:1592: void init_fts_doc_id_for_ref(dict_table_t , ulint ): Assertion `foreign->foreign_table' failed.

At the time of the assertion failure, an rename operation as part of ALTER TABLE t2 FORCE, ALGORITHM=COPY is in progress. It had initialized a new foreign constraint while the crashing thread was executing ha_innobase::index_first() for the DELETE statement. At the time of the crash, the rename operation is blocked here:

10.6 ba6bf7ad9e52c1dc31a22a619c17e1bb55b46d5d
#18 0x0000556736e62ab0 in dict_foreign_error_report_low (file=0x55673912b7b0, name=0x3b9c68028ee8 "test/t2") at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:2840
#19 dict_foreign_error_report (file=file@entry=0x55673912b7b0, fk=0x3b9c68028e68, msg=0x55673614f93a "there is no index in the table which would contain\nthe columns as the first columns, or the data types in the\ntable do not match the ones in the referenced table\nor one of the ON ... SET NULL columns "...) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:2858
#20 0x0000556736e6247e in dict_foreign_add_to_cache (foreign=foreign@entry=0x3b9c68028e68, col_names=col_names@entry=0x0, check_charsets=false, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_NONE) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:2976
#21 0x0000556736e76a2e in dict_load_foreign (table_name=0x6ab222e74f30 "test/t2", uncommitted=false, col_names=0x0, trx_id=72, check_charsets=false, id=<optimized out>, ignore_err=DICT_ERR_IGNORE_NONE, fk_tables=std::deque with 0 elements, check_recursive=<optimized out>) at /mariadb/10.6/storage/innobase/dict/dict0load.cc:3052
#22 dict_load_foreigns (table_name=table_name@entry=0x6ab222e74f30 "test/t2", col_names=col_names@entry=0x0, trx_id=72, check_charsets=false, ignore_err=DICT_ERR_IGNORE_NONE, fk_tables=std::deque with 0 elements) at /mariadb/10.6/storage/innobase/dict/dict0load.cc:3187
#23 0x00005567370b773b in row_rename_table_for_mysql (old_name=<optimized out>, old_name@entry=0x6ab222e74d30 "test/#sql-backup-11603c-5", new_name=new_name@entry=0x6ab222e74f30 "test/t2", trx=trx@entry=0x2de05eb72180, use_fk=true) at /mariadb/10.6/storage/innobase/row/row0mysql.cc:2870
#24 0x0000556736e17266 in innobase_rename_table (trx=trx@entry=0x2de05eb72180, from=from@entry=0x6ab222e75de0 "./test/#sql-backup-11603c-5", to=to@entry=0x6ab222e75be0 "./test/t2", use_fk=true) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:13824
#25 0x0000556736e177b7 in ha_innobase::rename_table (this=<optimized out>, from=0x6ab222e75de0 "./test/#sql-backup-11603c-5", to=0x6ab222e75be0 "./test/t2") at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:14230
#26 0x0000556736b57744 in mysql_rename_table (base=<optimized out>, old_db=0x6ab222e76bd0, old_name=0x6ab222e760b0, new_db=0x6ab222e76bd0, new_name=new_name@entry=0x6ab222e76c00, id=0x6ab222e76c70, flags=65) at /mariadb/10.6/sql/sql_table.cc:5055
#27 0x0000556736b5fdf8 in mysql_alter_table (thd=thd@entry=0x3b9c680028b8, new_db=<optimized out>, new_name=new_name@entry=0x3b9c680079a8, create_info=0x6ab222e78b20, table_list=<optimized out>, recreate_info=<optimized out>, alter_info=<optimized out>, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>, if_exists=<optimized out>) at /mariadb/10.6/sql/sql_table.cc:10892

Marko Mäkelä added a comment - 2023-11-29 12:12 The test case reproduces a different crash on a recent 10.6: 10.6 ba6bf7ad9e52c1dc31a22a619c17e1bb55b46d5d mysqltest: At line 36: query 'DELETE FROM t1 ORDER BY a LIMIT 5' failed: <Unknown> (2013): Lost connection to server during query … mariadbd: /mariadb/10.6/storage/innobase/row/row0mysql.cc:1592: void init_fts_doc_id_for_ref(dict_table_t *, ulint *): Assertion `foreign->foreign_table' failed. At the time of the assertion failure, an rename operation as part of ALTER TABLE t2 FORCE, ALGORITHM=COPY is in progress. It had initialized a new foreign constraint while the crashing thread was executing ha_innobase::index_first() for the DELETE statement. At the time of the crash, the rename operation is blocked here: 10.6 ba6bf7ad9e52c1dc31a22a619c17e1bb55b46d5d #18 0x0000556736e62ab0 in dict_foreign_error_report_low (file=0x55673912b7b0, name=0x3b9c68028ee8 "test/t2") at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:2840 #19 dict_foreign_error_report (file=file@entry=0x55673912b7b0, fk=0x3b9c68028e68, msg=0x55673614f93a "there is no index in the table which would contain\nthe columns as the first columns, or the data types in the\ntable do not match the ones in the referenced table\nor one of the ON ... SET NULL columns "...) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:2858 #20 0x0000556736e6247e in dict_foreign_add_to_cache (foreign=foreign@entry=0x3b9c68028e68, col_names=col_names@entry=0x0, check_charsets=false, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_NONE) at /mariadb/10.6/storage/innobase/dict/dict0dict.cc:2976 #21 0x0000556736e76a2e in dict_load_foreign (table_name=0x6ab222e74f30 "test/t2", uncommitted=false, col_names=0x0, trx_id=72, check_charsets=false, id=<optimized out>, ignore_err=DICT_ERR_IGNORE_NONE, fk_tables=std::deque with 0 elements, check_recursive=<optimized out>) at /mariadb/10.6/storage/innobase/dict/dict0load.cc:3052 #22 dict_load_foreigns (table_name=table_name@entry=0x6ab222e74f30 "test/t2", col_names=col_names@entry=0x0, trx_id=72, check_charsets=false, ignore_err=DICT_ERR_IGNORE_NONE, fk_tables=std::deque with 0 elements) at /mariadb/10.6/storage/innobase/dict/dict0load.cc:3187 #23 0x00005567370b773b in row_rename_table_for_mysql (old_name=<optimized out>, old_name@entry=0x6ab222e74d30 "test/#sql-backup-11603c-5", new_name=new_name@entry=0x6ab222e74f30 "test/t2", trx=trx@entry=0x2de05eb72180, use_fk=true) at /mariadb/10.6/storage/innobase/row/row0mysql.cc:2870 #24 0x0000556736e17266 in innobase_rename_table (trx=trx@entry=0x2de05eb72180, from=from@entry=0x6ab222e75de0 "./test/#sql-backup-11603c-5", to=to@entry=0x6ab222e75be0 "./test/t2", use_fk=true) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:13824 #25 0x0000556736e177b7 in ha_innobase::rename_table (this=<optimized out>, from=0x6ab222e75de0 "./test/#sql-backup-11603c-5", to=0x6ab222e75be0 "./test/t2") at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:14230 #26 0x0000556736b57744 in mysql_rename_table (base=<optimized out>, old_db=0x6ab222e76bd0, old_name=0x6ab222e760b0, new_db=0x6ab222e76bd0, new_name=new_name@entry=0x6ab222e76c00, id=0x6ab222e76c70, flags=65) at /mariadb/10.6/sql/sql_table.cc:5055 #27 0x0000556736b5fdf8 in mysql_alter_table (thd=thd@entry=0x3b9c680028b8, new_db=<optimized out>, new_name=new_name@entry=0x3b9c680079a8, create_info=0x6ab222e78b20, table_list=<optimized out>, recreate_info=<optimized out>, alter_info=<optimized out>, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>, if_exists=<optimized out>) at /mariadb/10.6/sql/sql_table.cc:10892

Marko Mäkelä added a comment - 2023-12-01 12:36

I can reproduce crashes even when the InnoDB persistent statistics are disabled (CREATE TABLE…STATS_PERSISTENT=0). Enabling the statistics on the parent table t1 might improve reproducibility. When there are no persistent statistics enabled on t1, I can reproduce a different type of failure that is more like the one in the Description:

11.0 b42f3189964a5a443a1f43645f9c3a60499b5401
2023-12-01 14:10:30 5 [ERROR] InnoDB: In ALTER TABLE `test`.`t2` has or is referenced in foreign key constraints which are not compatible with the new table definition.
2023-12-01 14:10:30 4 [ERROR] InnoDB: (Lock wait timeout) while getting next doc id for table `test`.`#sql-alter-24c979-5`
safe_mutex: Trying to destroy a mutex cache->lock that was locked at /mariadb/11/storage/innobase/fts/fts0fts.cc, line 4813 at /mariadb/11/storage/innobase/fts/fts0fts.cc, line 265

As far as I can tell, the root cause of this crash is that during the final phase of ALTER TABLE t2 FORCE, ALGORITHM=COPY, no MDL on the parent table t1 is being acquired, not MDL_EXCLUSIVE nor in any other mode.

Both ha_innobase::get_parent_foreign_key_list() and ha_innobase::get_foreign_key_list() are being invoked during the execution of ALTER TABLE t2 FORCE, ALGORITHM=COPY; the latter even twice. Both are returning the correct number of elements: 0 constraints referencing parent tables, and 2 constraints referenced by a child table.

The ha_innobase::rename_table() is part of committing the operation, so it really must be covered by MDL_EXCLUSIVE on both affected tables. For some reason, the SQL layer is ignoring the elements returned by both invocations of ha_innobase::get_foreign_key_list() and fails to acquire MDL_EXCLUSIVE on the table t1.

If I change the test to send ALTER TABLE t2 FORCE, ALGORITHM=INPLACE (instead of ALGORITHM=COPY) and allow that statement to succeed, then the test will pass 22×100 runs on 11.0. This could be because starting with 10.6, InnoDB should acquire sufficient exclusive table locks to cover the connected tables, even if the metadata lock (MDL) coverage were insufficient. In 10.4 and 10.5 also that variant could crash.

Marko Mäkelä added a comment - 2023-12-01 12:36 I can reproduce crashes even when the InnoDB persistent statistics are disabled ( CREATE TABLE…STATS_PERSISTENT=0 ). Enabling the statistics on the parent table t1 might improve reproducibility. When there are no persistent statistics enabled on t1 , I can reproduce a different type of failure that is more like the one in the Description: 11.0 b42f3189964a5a443a1f43645f9c3a60499b5401 2023-12-01 14:10:30 5 [ERROR] InnoDB: In ALTER TABLE `test`.`t2` has or is referenced in foreign key constraints which are not compatible with the new table definition. 2023-12-01 14:10:30 4 [ERROR] InnoDB: (Lock wait timeout) while getting next doc id for table `test`.`#sql-alter-24c979-5` safe_mutex: Trying to destroy a mutex cache->lock that was locked at /mariadb/11/storage/innobase/fts/fts0fts.cc, line 4813 at /mariadb/11/storage/innobase/fts/fts0fts.cc, line 265 As far as I can tell, the root cause of this crash is that during the final phase of ALTER TABLE t2 FORCE, ALGORITHM=COPY , no MDL on the parent table t1 is being acquired, not MDL_EXCLUSIVE nor in any other mode. Both ha_innobase::get_parent_foreign_key_list() and ha_innobase::get_foreign_key_list() are being invoked during the execution of ALTER TABLE t2 FORCE, ALGORITHM=COPY ; the latter even twice. Both are returning the correct number of elements: 0 constraints referencing parent tables, and 2 constraints referenced by a child table. The ha_innobase::rename_table() is part of committing the operation, so it really must be covered by MDL_EXCLUSIVE on both affected tables. For some reason, the SQL layer is ignoring the elements returned by both invocations of ha_innobase::get_foreign_key_list() and fails to acquire MDL_EXCLUSIVE on the table t1 . If I change the test to send ALTER TABLE t2 FORCE, ALGORITHM=INPLACE (instead of ALGORITHM=COPY ) and allow that statement to succeed, then the test will pass 22×100 runs on 11.0. This could be because starting with 10.6, InnoDB should acquire sufficient exclusive table locks to cover the connected tables, even if the metadata lock (MDL) coverage were insufficient. In 10.4 and 10.5 also that variant could crash.

Marko Mäkelä added a comment - 2023-12-01 13:42

I tested the ALGORITHM=INPLACE variant in 10.4: 66×100 times pass. The ALGORITHM=COPY variant with STATS_PERSISTENT=0 took some time to crash, but it does crash:

10.4 5f89045221717533994da01fc270d4851ccdc06c
#3 0x00005601b5563d35 in handle_fatal_signal (sig=11) at /mariadb/10.4/sql/signal_handler.cc:369
#4 <signal handler called>
#5 0x00007f0ff24c79d4 in std::_Rb_tree_increment(std::_Rb_tree_node_base const*) () at ../../../../../src/libstdc++-v3/src/c++98/tree.cc:89
#6 0x00005601b5b93aab in std::_Rb_tree_const_iterator<dict_foreign_t*>::operator++ (this=<synthetic pointer>) at /usr/include/c++/13/bits/stl_tree.h:366
#7 init_fts_doc_id_for_ref (table=table@entry=0x7f0f801f8470, depth=depth@entry=0x7f0fec0bf2c8) at /mariadb/10.4/storage/innobase/row/row0mysql.cc:1686
#8 0x00005601b5b977ae in row_update_for_mysql (prebuilt=0x7f0f80076690) at /mariadb/10.4/storage/innobase/row/row0mysql.cc:1742
#9 0x00005601b595cfe4 in ha_innobase::delete_row (this=0x7f0f800dff20, record=0x7f0f801cff78 "\377\031") at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:9081
#10 0x00005601b54d0ba6 in handler::ha_delete_row (this=0x7f0f800dff20, buf=0x7f0f801cff78 "\377\031") at /mariadb/10.4/sql/handler.cc:6992
#11 0x00005601b56268f2 in TABLE::delete_row (this=this@entry=0x7f0f8000d078) at /mariadb/10.4/sql/sql_delete.cc:292
#12 0x00005601b5625d27 in mysql_delete (thd=thd@entry=0x7f0f80000d38, table_list=0x7f0f80013998, conds=<optimized out>, order_list=order_list@entry=0x7f0f80005740, limit=1, options=<optimized out>, result=<optimized out>) at /mariadb/10.4/sql/sql_delete.cc:826
#13 0x00005601b5661712 in mysql_execute_command (thd=thd@entry=0x7f0f80000d38) at /mariadb/10.4/sql/sql_parse.cc:4819
#14 0x00005601b5666869 in mysql_parse (thd=thd@entry=0x7f0f80000d38, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f0fec0c0390, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mariadb/10.4/sql/sql_parse.cc:8062
#15 0x00005601b56682b4 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f0f80000d38, packet=packet@entry=0x7f0f8003e1b9 "DELETE FROM t1 ORDER BY a LIMIT 5", packet_length=packet_length@entry=33, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mariadb/10.4/sql/sql_parse.cc:1857

At this point of time, the execution of ALTER TABLE t2 FORCE, ALGORITHM=COPY; had apparently completed.

Marko Mäkelä added a comment - 2023-12-01 13:42 I tested the ALGORITHM=INPLACE variant in 10.4: 66×100 times pass. The ALGORITHM=COPY variant with STATS_PERSISTENT=0 took some time to crash, but it does crash: 10.4 5f89045221717533994da01fc270d4851ccdc06c #3 0x00005601b5563d35 in handle_fatal_signal (sig=11) at /mariadb/10.4/sql/signal_handler.cc:369 #4 <signal handler called> #5 0x00007f0ff24c79d4 in std::_Rb_tree_increment(std::_Rb_tree_node_base const*) () at ../../../../../src/libstdc++-v3/src/c++98/tree.cc:89 #6 0x00005601b5b93aab in std::_Rb_tree_const_iterator<dict_foreign_t*>::operator++ (this=<synthetic pointer>) at /usr/include/c++/13/bits/stl_tree.h:366 #7 init_fts_doc_id_for_ref (table=table@entry=0x7f0f801f8470, depth=depth@entry=0x7f0fec0bf2c8) at /mariadb/10.4/storage/innobase/row/row0mysql.cc:1686 #8 0x00005601b5b977ae in row_update_for_mysql (prebuilt=0x7f0f80076690) at /mariadb/10.4/storage/innobase/row/row0mysql.cc:1742 #9 0x00005601b595cfe4 in ha_innobase::delete_row (this=0x7f0f800dff20, record=0x7f0f801cff78 "\377\031") at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:9081 #10 0x00005601b54d0ba6 in handler::ha_delete_row (this=0x7f0f800dff20, buf=0x7f0f801cff78 "\377\031") at /mariadb/10.4/sql/handler.cc:6992 #11 0x00005601b56268f2 in TABLE::delete_row (this=this@entry=0x7f0f8000d078) at /mariadb/10.4/sql/sql_delete.cc:292 #12 0x00005601b5625d27 in mysql_delete (thd=thd@entry=0x7f0f80000d38, table_list=0x7f0f80013998, conds=<optimized out>, order_list=order_list@entry=0x7f0f80005740, limit=1, options=<optimized out>, result=<optimized out>) at /mariadb/10.4/sql/sql_delete.cc:826 #13 0x00005601b5661712 in mysql_execute_command (thd=thd@entry=0x7f0f80000d38) at /mariadb/10.4/sql/sql_parse.cc:4819 #14 0x00005601b5666869 in mysql_parse (thd=thd@entry=0x7f0f80000d38, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f0fec0c0390, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mariadb/10.4/sql/sql_parse.cc:8062 #15 0x00005601b56682b4 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f0f80000d38, packet=packet@entry=0x7f0f8003e1b9 "DELETE FROM t1 ORDER BY a LIMIT 5", packet_length=packet_length@entry=33, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /mariadb/10.4/sql/sql_parse.cc:1857 At this point of time, the execution of ALTER TABLE t2 FORCE, ALGORITHM=COPY; had apparently completed.

MariaDB Server

InnoDB: Failing assertion: lock->lock_word == X_LOCK_DECR or safe_mutex: Trying to destroy a mutex cache->lock that was locked

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration