[MDEV-27783] InnoDB: Failing assertion: table->get_ref_count() == 0 upon ALTER TABLE ... MODIFY COLUMN Created: 2022-02-09  Updated: 2022-08-05  Resolved: 2022-04-08

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.6.6
Fix Version/s: 10.6.8

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: affects-tests, rr-profile-analyzed

Attachments: File c00000.yy     File rqg.log     File simp_mix_table_stress_innodb_dml1.cfg    
Issue Links:
Relates
relates to MDEV-29250 InnoDB: Failing assertion: table->get... Closed

 Description   

origin/10.6 8d742fe4acb91652fcbeb36506d20ead4ff19e83 2022-02-01T19:50:08+05:30
compiled with debug
 
# 2022-02-08T13:09:59 [3414940] | [rr 3417576 1062259]2022-02-08 12:59:14 0x7ffe91d1d700[rr 3417576 1062262]  InnoDB: Assertion failure in file /data/Server/10.6/storage/innobase/dict/dict0dict.cc line 1824
# 2022-02-08T13:09:59 [3414940] | [rr 3417576 1062264]InnoDB: Failing assertion: table->get_ref_count() == 0
Query: ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text
# 2022-02-08T13:09:59 [3414940] | [rr 3417576 1083366]Status: KILL_TIMEOUT
 
(rr) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000072951fbf3859 in __GI_abort () at abort.c:79
#2  0x000055d44cf52045 in ut_dbg_assertion_failed (expr=0x55d44e1ad3a0 "table->get_ref_count() == 0", file=0x55d44e1ad660 "/data/Server/10.6/storage/innobase/dict/dict0dict.cc", line=1824)
    at /data/Server/10.6/storage/innobase/ut/ut0dbg.cc:60
#3  0x000055d44d09c2ec in dict_sys_t::remove (this=0x55d44f09f280 <dict_sys>, table=0x6180001cf508, lru=false, keep=false) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:1824
#4  0x000055d44d118db3 in trx_t::commit (this=0x6fd74f72c1c8, deleted=std::vector of length 17, capacity 32 = {...}) at /data/Server/10.6/storage/innobase/dict/drop.cc:249
#5  0x000055d44ca7bb92 in ha_innobase::delete_table (this=0x62b00015ba00, name=0x7ffe91d17380 "./test/#sql-backup-3425e8-37") at /data/Server/10.6/storage/innobase/handler/ha_innodb.cc:13636
#6  0x000055d44c15fc5c in hton_drop_table (hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37") at /data/Server/10.6/sql/handler.cc:576
#7  0x000055d44c16c57b in ha_delete_table (thd=0x62b000150218, hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37", db=0x7ffe91d191b0, alias=0x7ffe91d17890, generate_warning=false)
    at /data/Server/10.6/sql/handler.cc:3100
#8  0x000055d44bbd5efc in quick_rm_table (thd=0x62b000150218, base=0x615000002118, db=0x7ffe91d191b0, table_name=0x7ffe91d17890, flags=3, table_path=0x0) at /data/Server/10.6/sql/sql_table.cc:1919
#9  0x000055d44bc11f1f in mysql_alter_table (thd=0x62b000150218, new_db=0x62b000154c18, new_name=0x62b000155030, create_info=0x7ffe91d1a650, table_list=0x62b0001573d0, alter_info=0x7ffe91d1a520, order_num=0, order=0x0, 
    ignore=false, if_exists=false) at /data/Server/10.6/sql/sql_table.cc:10659
#10 0x000055d44bd9cc3e in Sql_cmd_alter_table::execute (this=0x62b000157c08, thd=0x62b000150218) at /data/Server/10.6/sql/sql_alter.cc:542
#11 0x000055d44b9a0fe0 in mysql_execute_command (thd=0x62b000150218, is_called_from_prepared_stmt=false) at /data/Server/10.6/sql/sql_parse.cc:5996
#12 0x000055d44b9ad3c8 in mysql_parse (thd=0x62b000150218, rawbuf=0x62b000157238 "ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */", length=96, 
    parser_state=0x7ffe91d1bb20) at /data/Server/10.6/sql/sql_parse.cc:8029
#13 0x000055d44b98576d in dispatch_command (command=COM_QUERY, thd=0x62b000150218, packet=0x629000c8a219 " ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */ ", 
    packet_length=98, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1896
#14 0x000055d44b982b45 in do_command (thd=0x62b000150218, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1404
#15 0x000055d44bd83074 in do_handle_one_connection (connect=0x608000045b38, put_in_cache=true) at /data/Server/10.6/sql/sql_connect.cc:1418
#16 0x000055d44bd82900 in handle_one_connection (arg=0x608000003638) at /data/Server/10.6/sql/sql_connect.cc:1312
#17 0x00004005048e9609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#18 0x000072951fcf0293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
(rr)
sdp:/data/results/1644351887/TBR-1069/dev/shm/rqg/1644351887/236/1/rr
 
RQG
===
# git clone https://github.com/mleich1/rqg --branch experimental RQG
#
# GIT_SHOW: HEAD -> experimental, origin/experimental 3dd8aeba1eee7ed7334e5e925f71f0c6eb70a7f4 2022-02-08T15:24:56+01:00
# rqg.pl  : Version 4.0.4 (2021-12)
#
# $RQG_HOME/rqg.pl \
# --duration=300 \
# --queries=10000000 \
# --no_mask \
# --seed=random \
# --max_gd_duration=1200 \
# --engine=InnoDB \
# --gendata_sql=conf/mariadb/table_stress.sql \
# --gendata=conf/mariadb/table_stress.zz \
# --rpl_mode=none \
# --mysqld=--loose-innodb_read_only_compressed=OFF \
# --mysqld=--connect_timeout=60 \
# --mysqld=--log_bin_trust_function_creators=1 \
# --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
# --mysqld=--loose-idle_transaction_timeout=0 \
# --mysqld=--log-output=none \
# --mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
# --mysqld=--loose-idle_write_transaction_timeout=0 \
# --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
# --mysqld=--net_read_timeout=30 \
# --mysqld=--innodb-buffer-pool-size=5M \
# --mysqld=--loose-table_lock_wait_timeout=50 \
# --mysqld=--innodb_page_size=4K \
# --mysqld=--sync-binlog=1 \
# --mysqld=--lock-wait-timeout=86400 \
# --mysqld=--innodb-lock-wait-timeout=50 \
# --mysqld=--innodb_purge_rseg_truncate_frequency=2 \
# --mysqld=--log-bin \
# --mysqld=--loose-max-statement-time=30 \
# --mysqld=--net_write_timeout=60 \
# --mysqld=--plugin-load-add=file_key_management.so \
# --mysqld=--wait_timeout=28800 \
# --mysqld=--interactive_timeout=28800 \
# --mysqld=--slave_net_timeout=60 \
# --mysqld=--loose-plugin-load-add=provider_lz4.so \
# --mysqld=--loose-idle_readonly_transaction_timeout=0 \
# --reporters=Backtrace,Deadlock1,ErrorLog \
# --validators=None \
# --grammar=/data/results/1644351887/c00000.yy \
# --threads=5 \
# <local settings>



 Comments   
Comment by Matthias Leich [ 2022-02-09 ]

c00000.yy is a simplified derivate of conf/mariadb/table_stress_innodb_dml.yy.
simp_mix_table_stress_innodb_dml1.cfg was used during test simplification and bug replay.
 
Error pattern for RQG
[ 'TBR-1069-ExMDEV-27017', 'InnoDB: Assertion failure in file .{1,200}dict0dict.cc line.+InnoDB: Failing assertion: table->get_ref_count\(\) == 0.+RESULT: The RQG run ended with status STATUS_SERVER_CRASHED' ],

Comment by Thirunarayanan Balathandayuthapani [ 2022-02-09 ]

Thread 3:
(rr) where
#0  ha_innobase::delete_table (this=0x62b00015ba00, name=0x7ffe91d17380 "./test/#sql-backup-3425e8-37")
    at /data/Server/10.6/storage/innobase/handler/ha_innodb.cc:13459
#1  0x000055d44c15fc5c in hton_drop_table (hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37")
    at /data/Server/10.6/sql/handler.cc:576
#2  0x000055d44c16c57b in ha_delete_table (thd=0x62b000150218, hton=0x615000002118, path=0x7ffe91d17380 "./test/#sql-backup-3425e8-37", 
    db=0x7ffe91d191b0, alias=0x7ffe91d17890, generate_warning=false) at /data/Server/10.6/sql/handler.cc:3100
#3  0x000055d44bbd5efc in quick_rm_table (thd=0x62b000150218, base=0x615000002118, db=0x7ffe91d191b0, table_name=0x7ffe91d17890, flags=3, 
    table_path=0x0) at /data/Server/10.6/sql/sql_table.cc:1919
#4  0x000055d44bc11f1f in mysql_alter_table (thd=0x62b000150218, new_db=0x62b000154c18, new_name=0x62b000155030, create_info=0x7ffe91d1a650, 
    table_list=0x62b0001573d0, alter_info=0x7ffe91d1a520, order_num=0, order=0x0, ignore=false, if_exists=false)
    at /data/Server/10.6/sql/sql_table.cc:10659
#5  0x000055d44bd9cc3e in Sql_cmd_alter_table::execute (this=0x62b000157c08, thd=0x62b000150218) at /data/Server/10.6/sql/sql_alter.cc:542
#6  0x000055d44b9a0fe0 in mysql_execute_command (thd=0x62b000150218, is_called_from_prepared_stmt=false)
    at /data/Server/10.6/sql/sql_parse.cc:5996
#7  0x000055d44b9ad3c8 in mysql_parse (thd=0x62b000150218, 
    rawbuf=0x62b000157238 "ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */", length=96, 
    parser_state=0x7ffe91d1bb20) at /data/Server/10.6/sql/sql_parse.cc:8029
#8  0x000055d44b98576d in dispatch_command (command=COM_QUERY, thd=0x62b000150218, 
    packet=0x629000c8a219 " ALTER TABLE t2 MODIFY COLUMN col_int INTEGER AFTER col_text /* E_R Thread1 QNO 1142 CON_ID 55 */ ", 
    packet_length=98, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1896
#9  0x000055d44b982b45 in do_command (thd=0x62b000150218, blocking=true) at /data/Server/10.6/sql/sql_parse.cc:1404
#10 0x000055d44bd83074 in do_handle_one_connection (connect=0x608000045b38, put_in_cache=true) at /data/Server/10.6/sql/sql_connect.cc:1418
#11 0x000055d44bd82900 in handle_one_connection (arg=0x608000003638) at /data/Server/10.6/sql/sql_connect.cc:1312
#12 0x00004005048e9609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#13 0x000072951fcf0293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
thread 26:
(rr) where
#0  0x000055d44cbf7d74 in dict_sys_t::find_table (this=0x55d44f09f280 <dict_sys>, id=671)
    at /data/Server/10.6/storage/innobase/include/dict0dict.h:1470
#1  0x000055d44d09580f in dict_table_open_on_id (table_id=671, dict_locked=false, table_op=DICT_TABLE_OP_NORMAL, thd=0x62b000023218, 
    mdl=0x61a00000aaa8) at /data/Server/10.6/storage/innobase/dict/dict0dict.cc:836
#2  0x000055d44ce2be08 in row_purge_parse_undo_rec (node=0x61a00000a908, undo_rec=0x621000abe3d8 "", thr=0x616000058cc0, 
    updated_extern=0x10b27ab59820) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1028
#3  0x000055d44ce2d6ba in row_purge (node=0x61a00000a908, undo_rec=0x621000abe3d8 "", thr=0x616000058cc0)
    at /data/Server/10.6/storage/innobase/row/row0purge.cc:1206
#4  0x000055d44ce2db08 in row_purge_step (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/row/row0purge.cc:1258
#5  0x000055d44cd1ee45 in que_thr_step (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:653
#6  0x000055d44cd1f1ed in que_run_threads_low (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:709
#7  0x000055d44cd1f38f in que_run_threads (thr=0x616000058cc0) at /data/Server/10.6/storage/innobase/que/que0que.cc:729
#8  0x000055d44ceabaa7 in srv_task_execute () at /data/Server/10.6/storage/innobase/srv/srv0srv.cc:1716

Purge thread is waiting at dict_table_open_on_id() after checking check_stop_FTS() and at that time, InnoDB ddl does stop_FTS() ,
make sure that fts table doesn't have any other ref count. So there is still race condition can occur between purge thread and DDL.

Comment by Marko Mäkelä [ 2022-04-04 ]

I think that we must make dict_table_open_on_id() in row_purge_parse_undo_rec() avoid table->acquire() if purge_sys.must_wait_FTS() holds. Also, purge_sys_t::stop_FTS() must be protected by exclusive dict_sys.latch to avoid a race between those functions.

Comment by Matthias Leich [ 2022-04-08 ]

origin/bb-10.6-MDEV-27783 27b0030b9dc48d1e5264d084e4a917700271c8ab 2022-04-07T10:32:51+05:30
behaved well in RQG testing. The problems hit are either already known or not specific to the MDEV.

Generated at Thu Feb 08 09:55:33 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.