[MDEV-30037] InnoDB: Failing assertion: table->n_rec_locks == 0 Created: 2022-11-18  Updated: 2022-11-25

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6.12
Fix Version/s: 10.6

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Unresolved Votes: 0
Labels: foreign-keys, fulltext

Attachments: File FK.cfg     File REPLAY_SIMP10_RR.sh     File table_stress_innodb_fk-micro.yy    

 Description    

I hit during testing on origin/10.6 9aea7d83c8d006519bdf1f3269136b3756ed7548 2022-11-17T08:37:35+02:00
 
# 2022-11-18T10:09:01 [2517410] | 2022-11-18 10:08:40 0x7f9f03aec640  InnoDB: Assertion failure in file /data/Server/10.6/storage/innobase/dict/dict0dict.cc line 1862
 
# 2022-11-18T10:09:01 [2517410] | InnoDB: Failing assertion: table->n_rec_locks == 0
 
when running the following scenario
 
1. Start the DB server
 
2. Session 1 runs
 
     CREATE SCHEMA birth ;
 
    CREATE TABLE birth . parent (
 
         col1 INT PRIMARY KEY, col_text TEXT,
 
         col_text_g TEXT GENERATED ALWAYS AS (SUBSTR(col_text,1,499))
 
    ;         (storage engine is InnoDB)
 
    CREATE TABLE birth . child LIKE birth . parent ;
 
    ALTER TABLE birth . child ADD FOREIGN KEY (col1) REFERENCES birth . parent(col1) ;
 
    RENAME TABLE birth . parent TO test . parent , birth . child TO test . child ;
 
3. Session 1 runs a stream of
 
    INSERT INTO test . child (col1) VALUES ( <random int between 9 and 64 ); COMMIT ;
 
    Session 2 runs concurrent a stream of
 
    ALTER TABLE test . parent ADD FULLTEXT ( col_text ) ;



 Comments   
Comment by Matthias Leich [ 2022-11-25 ] 

rr traces generated on origin/10.6 9aea7d83c8d006519bdf1f3269136b3756ed7548 2022-11-17T08:37:35+02:00 build with debug+asan+Og
 
 
 
[rr 3389988 42886]2022-11-25 08:50:28 0x32d2414de640[rr 3389988 42891]  InnoDB: Assertion failure in file /data/Server/10.6/storage/innobase/dict/dict0dict.cc line 1862
 
(rr) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=55878620145216) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=55878620145216) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=55878620145216, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x00004aa65bab7476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x00004aa65ba9d7f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x000055f5f2dbdb87 in ut_dbg_assertion_failed (expr=expr@entry=0x55f5f3c63960 "table->n_rec_locks == 0", file=file@entry=0x55f5f3c5a940 "/data/Server/10.6/storage/innobase/dict/dict0dict.cc", line=line@entry=1862)
 
    at /data/Server/10.6/storage/innobase/ut/ut0dbg.cc:60
 
#6  0x000055f5f2f53542 in dict_sys_t::remove (this=<optimized out>, table=table@entry=0x61800007ed08, lru=lru@entry=false, keep=keep@entry=false) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:1862
 
#7  0x000055f5f28df26d in innobase_reload_table (thd=<optimized out>, table=0x61800007ed08, table_name=..., ctx=...) at /data/Server/10.6/storage/innobase/handler/handler0alter.cc:10336
 
#8  0x000055f5f2903aa9 in ha_innobase::commit_inplace_alter_table (this=<optimized out>, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>)
 
    at /data/Server/10.6/storage/innobase/handler/handler0alter.cc:11475
 
#9  0x000055f5f1df6b8f in handler::ha_commit_inplace_alter_table (this=0x61d0007df0b8, altered_table=altered_table@entry=0x32d2414d8bf0, ha_alter_info=ha_alter_info@entry=0x32d2414d84f0, commit=commit@entry=true)
 
    at /data/Server/10.6/sql/handler.cc:5218
 
#10 0x000055f5f17b7b2e in mysql_inplace_alter_table (thd=thd@entry=0x62b00012d218, table_list=<optimized out>, table=table@entry=0x6190004ab598, altered_table=altered_table@entry=0x32d2414d8bf0, 
    ha_alter_info=ha_alter_info@entry=0x32d2414d84f0, target_mdl_request=target_mdl_request@entry=0x32d2414d85f0, ddl_log_state=<optimized out>, trigger_param=<optimized out>, alter_ctx=<optimized out>)
 
    at /data/Server/10.6/sql/sql_table.cc:7481
 
#11 0x000055f5f17ee66c in mysql_alter_table (thd=thd@entry=0x62b00012d218, new_db=new_db@entry=0x62b000131c48, new_name=new_name@entry=0x62b000132060, create_info=0x32d2414daf70, table_list=table_list@entry=0x62b0001343c8, 
    alter_info=<optimized out>, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>, if_exists=<optimized out>) at /data/Server/10.6/sql/sql_table.cc:10347
 
#12 0x000055f5f198097d in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62b00012d218) at /data/Server/10.6/sql/sql_alter.cc:552
 
#13 0x000055f5f153f1c6 in mysql_execute_command (thd=thd@entry=0x62b00012d218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.6/sql/sql_parse.cc:5997
 
#14 0x000055f5f154157e in mysql_parse (thd=thd@entry=0x62b00012d218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x32d2414dc620) at /data/Server/10.6/sql/sql_parse.cc:8016
 
#15 0x000055f5f1547db9 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b00012d218, 
    packet=packet@entry=0x629000c2b219 "ALTER TABLE test.parent ADD FULLTEXT ( col_text ) /* E_R Thread2 QNO 5 CON_ID 18 */ ", packet_length=packet_length@entry=84, blocking=blocking@entry=true)
 
    at /data/Server/10.6/sql/sql_parse.cc:1896
 
#16 0x000055f5f154ce18 in do_command (thd=0x62b00012d218, blocking=blocking@entry=true) at /data/Server/10.6/sql/sql_parse.cc:1409
 
#17 0x000055f5f1968834 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x608000002fb8, put_in_cache=put_in_cache@entry=true) at /data/Server/10.6/sql/sql_connect.cc:1416
 
#18 0x000055f5f1968e9a in handle_one_connection (arg=0x608000002fb8) at /data/Server/10.6/sql/sql_connect.cc:1318
 
#19 0x00004aa65bb09b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#20 0x00004aa65bb9abb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
 
(rr)
 
sdp:/data/results/1669395011/TBR-1219$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
 
 
 
I hit with the same test less frequent
 
[rr 3393072 58303]mysqld: /data/Server/10.6/storage/innobase/include/sux_lock.h:85: void sux_lock<ssux>::free() [with ssux = ssux_lock_impl<false>]: Assertion `r->empty()' failed.
 
(rr) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=109951311324736) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=109951311324736) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=109951311324736, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x000072cd10834476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x000072cd1081a7f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x000072cd1081a71b in __assert_fail_base (fmt=0x72cd109cf150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x561d207905e0 "r->empty()", file=0x561d2078ce80 "/data/Server/10.6/storage/innobase/include/sux_lock.h", 
    line=85, function=<optimized out>) at ./assert/assert.c:92
 
#6  0x000072cd1082be96 in __GI___assert_fail (assertion=0x561d207905e0 "r->empty()", file=0x561d2078ce80 "/data/Server/10.6/storage/innobase/include/sux_lock.h", line=85, 
    function=0x561d207904c0 "void sux_lock<ssux>::free() [with ssux = ssux_lock_impl<false>]") at ./assert/assert.c:101
 
#7  0x0000561d1f5fb219 in sux_lock<ssux_lock_impl<false> >::free (this=this@entry=0x616003ae5080) at /data/Server/10.6/storage/innobase/include/sux_lock.h:85
 
#8  0x0000561d1fc248c6 in dict_index_remove_from_cache_low (table=table@entry=0x61800011fd08, index=0x616003ae4f08, lru_evict=lru_evict@entry=0) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:2166
 
#9  0x0000561d1fc25847 in dict_sys_t::remove (this=<optimized out>, table=table@entry=0x61800011fd08, lru=lru@entry=false, keep=keep@entry=false) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:1887
 
#10 0x0000561d1f5b126d in innobase_reload_table (thd=<optimized out>, table=0x61800011fd08, table_name=..., ctx=...) at /data/Server/10.6/storage/innobase/handler/handler0alter.cc:10336
 
#11 0x0000561d1f5d5aa9 in ha_innobase::commit_inplace_alter_table (this=<optimized out>, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>)
 
    at /data/Server/10.6/storage/innobase/handler/handler0alter.cc:11475
 
#12 0x0000561d1eac8b8f in handler::ha_commit_inplace_alter_table (this=0x61d0009d26b8, altered_table=altered_table@entry=0x640008da4bf0, ha_alter_info=ha_alter_info@entry=0x640008da44f0, commit=commit@entry=true)
 
    at /data/Server/10.6/sql/handler.cc:5218
 
#13 0x0000561d1e489b2e in mysql_inplace_alter_table (thd=thd@entry=0x62b00012d218, table_list=<optimized out>, table=table@entry=0x619000583498, altered_table=altered_table@entry=0x640008da4bf0, 
    ha_alter_info=ha_alter_info@entry=0x640008da44f0, target_mdl_request=target_mdl_request@entry=0x640008da45f0, ddl_log_state=<optimized out>, trigger_param=<optimized out>, alter_ctx=<optimized out>)
 
    at /data/Server/10.6/sql/sql_table.cc:7481
 
#14 0x0000561d1e4c066c in mysql_alter_table (thd=thd@entry=0x62b00012d218, new_db=new_db@entry=0x62b000131c48, new_name=new_name@entry=0x62b000132060, create_info=0x640008da6f70, table_list=table_list@entry=0x62b0001343c8, 
    alter_info=<optimized out>, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>, if_exists=<optimized out>) at /data/Server/10.6/sql/sql_table.cc:10347
 
#15 0x0000561d1e65297d in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62b00012d218) at /data/Server/10.6/sql/sql_alter.cc:552
 
#16 0x0000561d1e2111c6 in mysql_execute_command (thd=thd@entry=0x62b00012d218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.6/sql/sql_parse.cc:5997
 
#17 0x0000561d1e21357e in mysql_parse (thd=thd@entry=0x62b00012d218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x640008da8620) at /data/Server/10.6/sql/sql_parse.cc:8016
 
#18 0x0000561d1e219db9 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b00012d218, 
    packet=packet@entry=0x629000c2b219 "ALTER TABLE test.parent ADD FULLTEXT ( col_text ) /* E_R Thread2 QNO 56 CON_ID 18 */ ", packet_length=packet_length@entry=85, blocking=blocking@entry=true)
 
    at /data/Server/10.6/sql/sql_parse.cc:1896
 
#19 0x0000561d1e21ee18 in do_command (thd=0x62b00012d218, blocking=blocking@entry=true) at /data/Server/10.6/sql/sql_parse.cc:1409
 
#20 0x0000561d1e63a834 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x608000002fb8, put_in_cache=put_in_cache@entry=true) at /data/Server/10.6/sql/sql_connect.cc:1416
 
#21 0x0000561d1e63ae9a in handle_one_connection (arg=0x608000002fb8) at /data/Server/10.6/sql/sql_connect.cc:1318
 
#22 0x000072cd10886b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#23 0x000072cd10917bb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
 
(rr)
 
sdp:/data/results/1669395011/TBR-1676$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
 
 
 
How to replay with RQG
 
===================
 
git clone https://github.com/mleich1/rqg  RQG
 
cd RQG
 
README.2nd describes which software to install in addition.
 
Store REPLAY_SIMP10_RR.sh , FK.cfg , table_stress_innodb_fk-micro.yy within the current directory.
 
 
 
./REPLAY_SIMP10_RR.sh FK.cfg <path where you installed the MariDB binaries>
 
     # Run till 10 RQG finished and replayed the bad effects described above.
 
     # The first call will likely fail and force you to make certain adjustments or install more software.

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