[MDEV-30393] InnoDB: Assertion failure in dict0dict.cc upon ADD FULLTEXT INDEX Created: 2023-01-12  Updated: 2023-01-24  Resolved: 2023-01-24

Status: Closed
Project: MariaDB Server
Component/s: Full-text Search, Storage Engine - InnoDB
Affects Version/s: 10.6, 10.7, 10.8, 10.9, 10.10, 10.11
Fix Version/s: 10.11.2, 10.6.12, 10.7.8, 10.8.7, 10.9.5, 10.10.3

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

Attachments: File TBR-1706.cfg     File TBR-1706.yy    

 Description    

origin/10.7 8356fb68c366b7f515f9060d964ee598653756a6 2023-01-04T14:52:25+02:00
 
 
 
A RQG test with two sessions running concurrent DDL could end up with
 
# 2023-01-12T04:26:35 [4067710] | [rr 4071411 168121]2023-01-12 04:19:58 0x340d2c5e0640[rr 4071411 168124]  InnoDB: Assertion failure in file /data/Server/10.7/storage/innobase/dict/dict0dict.cc line 4428
 
# 2023-01-12T04:26:35 [4067710] | Query (0x629000d89238): ALTER TABLE t7 ADD FULLTEXT KEY ( col_text, col_varchar )
 
# 2023-01-12T04:26:35 [4067710] | [rr 4071411 212106]Status: KILL_TIMEOUT
 
 
 
# 2023-01-12T04:24:44 [4067710] | Thread 3 (Thread 4071411.4074524 (mariadbd)):
 
# 2023-01-12T04:24:44 [4067710] | #0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=57231183578688) at ./nptl/pthread_kill.c:44
 
# 2023-01-12T04:24:44 [4067710] | #1  __pthread_kill_internal (signo=6, threadid=57231183578688) at ./nptl/pthread_kill.c:78
 
# 2023-01-12T04:24:44 [4067710] | #2  __GI___pthread_kill (threadid=57231183578688, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
# 2023-01-12T04:24:44 [4067710] | #3  0x00001dc33a898476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
# 2023-01-12T04:24:44 [4067710] | #4  0x00001dc33a87e7f3 in __GI_abort () at ./stdlib/abort.c:79
 
# 2023-01-12T04:24:44 [4067710] | #5  0x000056503e45fa57 in ut_dbg_assertion_failed (expr=expr@entry=0x0, file=file@entry=0x56503f357400 "/data/Server/10.7/storage/innobase/dict/dict0dict.cc", line=line@entry=4428) at /data/Server/10.7/storage/innobase/ut/ut0dbg.cc:60
 
# 2023-01-12T04:24:44 [4067710] | #6  0x000056503e5e855c in dict_table_check_for_dup_indexes (table=<optimized out>, check=check@entry=CHECK_ABORTED_OK) at /data/Server/10.7/storage/innobase/dict/dict0dict.cc:4428
 
# 2023-01-12T04:24:44 [4067710] | #7  0x000056503df89ea9 in ha_innobase::prepare_inplace_alter_table (this=0x61d0008458b8, altered_table=<optimized out>, ha_alter_info=0x340d2c5da560) at /data/Server/10.7/storage/innobase/handler/handler0alter.cc:7784
 
# 2023-01-12T04:24:44 [4067710] | #8  0x000056503d50ccd5 in handler::ha_prepare_inplace_alter_table (this=0x61d0008458b8, altered_table=altered_table@entry=0x340d2c5dac60, ha_alter_info=ha_alter_info@entry=0x340d2c5da560) at /data/Server/10.7/sql/handler.cc:5213
 
# 2023-01-12T04:24:44 [4067710] | #9  0x000056503cec451f in mysql_inplace_alter_table (thd=thd@entry=0x62b0001dc218, table_list=<optimized out>, table=table@entry=0x619000555f98, altered_table=<optimized out>, ha_alter_info=0x340d2c5da560, target_mdl_request=<optimized out>, ddl_log_state=<optimized out>, trigger_param=<optimized out>, alter_ctx=<optimized out>) at /data/Server/10.7/sql/sql_table.cc:7473
 
# 2023-01-12T04:24:44 [4067710] | #10 0x000056503cefd90b in mysql_alter_table (thd=thd@entry=0x62b0001dc218, new_db=new_db@entry=0x62b0001e0ce8, new_name=new_name@entry=0x62b0001e1108, create_info=0x340d2c5dcf70, table_list=<optimized out>, table_list@entry=0x629000d893c8, alter_info=<optimized out>, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>, if_exists=<optimized out>) at /data/Server/10.7/sql/sql_table.cc:10455
 
# 2023-01-12T04:24:44 [4067710] | #11 0x000056503d091ef6 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62b0001dc218) at /data/Server/10.7/sql/sql_alter.cc:554
 
# 2023-01-12T04:24:44 [4067710] | #12 0x000056503cc1744f in mysql_execute_command (thd=thd@entry=0x62b0001dc218, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /data/Server/10.7/sql/sql_parse.cc:5992
 
# 2023-01-12T04:24:44 [4067710] | #13 0x000056503cc1996c in mysql_parse (thd=thd@entry=0x62b0001dc218, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x340d2c5de620) at /data/Server/10.7/sql/sql_parse.cc:8017
 
# 2023-01-12T04:24:44 [4067710] | #14 0x000056503cc2019c in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62b0001dc218, packet=packet@entry=0x629000d7f219 "ALTER TABLE t7 ADD FULLTEXT KEY ( col_text, col_varchar ) /* E_R Thread2 QNO 40 CON_ID 17 */ ", packet_length=packet_length@entry=93, blocking=blocking@entry=true) at /data/Server/10.7/sql/sql_parse.cc:1894
 
# 2023-01-12T04:24:44 [4067710] | #15 0x000056503cc251fb in do_command (thd=0x62b0001dc218, blocking=blocking@entry=true) at /data/Server/10.7/sql/sql_parse.cc:1407
 
# 2023-01-12T04:24:44 [4067710] | #16 0x000056503d079748 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x6080000038b8, put_in_cache=put_in_cache@entry=true) at /data/Server/10.7/sql/sql_connect.cc:1416
 
# 2023-01-12T04:24:44 [4067710] | #17 0x000056503d079dae in handle_one_connection (arg=0x6080000038b8) at /data/Server/10.7/sql/sql_connect.cc:1318
 
# 2023-01-12T04:24:44 [4067710] | #18 0x00001dc33a8eab43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
# 2023-01-12T04:24:44 [4067710] | #19 0x00001dc33a97bbb4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
 
 
 
sdp:/data1/results/1673525776/TBR-1706$ _RR_TRACE_DIR=./1/rr rr replay --mark-stdio
 
 
 
RQG
 
===
 
# git clone https://github.com/mleich1/rqg --branch <pick the right branch> RQG
 
#
 
# GIT_SHOW: HEAD -> master, origin/master, origin/HEAD 2d66adf87b35c65c844dc849daae068d5d15c34b 2023-01-09T19:20:34+01:00
 
# rqg.pl  : Version 4.2.1 (2022-12)
 
#
 
# $RQG_HOME/rqg.pl \
 
# --duration=300 \
 
# --queries=10000000 \
 
# --no_mask \
 
# --seed=random \
 
# --engine=InnoDB \
 
# --gendata_sql=conf/mariadb/table_stress.sql \
 
# --gendata=conf/mariadb/table_stress.zz \
 
# --rpl_mode=none \
 
# --max_gd_duration=1200 \
 
# --mysqld=--interactive_timeout=28800 \
 
# --mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
# --mysqld=--plugin-load-add=file_key_management.so \
 
# --mysqld=--connect_timeout=60 \
 
# --mysqld=--loose-max-statement-time=30 \
 
# --mysqld=--loose-idle_transaction_timeout=0 \
 
# --mysqld=--loose-table_lock_wait_timeout=50 \
 
# --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
# --mysqld=--log-bin \
 
# --mysqld=--slave_net_timeout=60 \
 
# --mysqld=--loose-innodb_read_only_compressed=OFF \
 
# --mysqld=--innodb_rollback_on_timeout=ON \
 
# --mysqld=--innodb_adaptive_hash_index=on \
 
# --mysqld=--loose-plugin-load-add=provider_lz4.so \
 
# --mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
 
# --mysqld=--innodb-buffer-pool-size=256M \
 
# --mysqld=--net_read_timeout=30 \
 
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
# --mysqld=--innodb-lock-wait-timeout=50 \
 
# --mysqld=--wait_timeout=28800 \
 
# --mysqld=--innodb_page_size=32K \
 
# --mysqld=--log-output=none \
 
# --mysqld=--net_write_timeout=60 \
 
# --mysqld=--sync-binlog=1 \
 
# --mysqld=--log_bin_trust_function_creators=1 \
 
# --mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
 
# --mysqld=--lock-wait-timeout=86400 \
 
# --mysqld=--loose-idle_write_transaction_timeout=0 \
 
# --reporters=Backtrace,Deadlock,None \
 
# --validators=None \
 
# --grammar=TBR-1706.yy \
 
# --threads=2 \
 
# <local settings>
 
 
 
TBR-1706.yy
 
-------------------
 
add_accelerator:
 
    ADD FULLTEXT KEY ( col_text , col_varchar ) ;
 
 
 
c_t_begin:
 
    CREATE TABLE IF NOT EXISTS ;
 
 
 
c_t_mid:
 
    ( non_generated_cols ) ;
 
 
 
create_table:
 
    c_t_begin t4 c_t_mid ENGINE = InnoDB ROW_FORMAT = Redundant ;
 
    c_t_begin t7 c_t_mid ENGINE = InnoDB ROW_FORMAT = Compact PAGE_COMPRESSED=1 ENCRYPTED=YES ENCRYPTION_KEY_ID=33 ;
 
 
 
non_generated_cols:
 
    col1 INT PRIMARY KEY, col2 INT, col_int INTEGER , col_string INTEGER, col_varchar VARCHAR(500), col_text TEXT ;
 
 
 
thread1:
 
    ALTER TABLE t4 add_accelerator , add_accelerator |
 
    ALTER TABLE t7 add_accelerator , add_accelerator ;
 
 
 
thread1_connect:
 
    ;
 
 
 
thread1_init:
 
    create_table ;
 
 
 
thread2:
 
    ALTER TABLE t4 add_accelerator |
 
    ALTER TABLE t7 add_accelerator ;
 
 
 
thread2_connect:
 
    SET AUTOCOMMIT = 0; SET SESSION lock_wait_timeout = 2 ; SET SESSION innodb_lock_wait_timeout = 1 ;
 
 
 
thread2_init:
 
    ;



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2023-01-23 ]

Patch is in bb-10.6-MDEV-30393

Comment by Marko Mäkelä [ 2023-01-23 ]

Can you please show the stack trace where the transaction was committed or rolled back during ha_innobase::commit_inplace_alter_table()? What was the setting of innodb_rollback_on_timeout=ON? Which changes of the DDL operation were not undone as a result of this? Some stubs for ADD INDEX?

Comment by Thirunarayanan Balathandayuthapani [ 2023-01-24 ]

innodb_rollback_on_timeout is enabled and while trying to take lock on table stats table in commit phase, we get DB_LOCK_WAIT, and it leads to rollback of the transaction.
rollback_inplace_alter_table fails to clear the index stubs which were added as a part of prepare phase.

Let me paste the test case which produces the same stack trace:

--source include/have_innodb.inc
 
create table t1(f1 char(100), f2 char(100),fulltext(f1))engine=innodb;
 
insert into t1 values("mysql", "mariadb");
 
set DEBUG_DBUG="+d,stats_lock_fail";
 
--error ER_LOCK_WAIT_TIMEOUT
 
alter table t1 add fulltext `idx` (f2);
 
SET DEBUG_DBUG="-d,stats_lock_fail";
 
alter table t1 add fulltext `idx`(f2);
 
show create table t1;
 
drop table t1;

Stack trace:

stack_bottom = 0x7f2ab6265cd8 thread_stack 0x49000
 
mysys/stacktrace.c:212(my_print_stacktrace)[0x563fbedd0303]
 
sql/signal_handler.cc:238(handle_fatal_signal)[0x563fbe56df03]
 
??:0(__restore_rt)[0x7f2ac10d0980]
 
linux/raise.c:51(__GI_raise)[0x7f2ac0d0be87]
 
stdlib/abort.c:81(__GI_abort)[0x7f2ac0d0d7f1]
 
ut/ut0new.cc:84(ut_new_boot())[0x563fbebae559]
 
dict/dict0dict.cc:4426(dict_table_check_for_dup_indexes(dict_table_t const*, check_name))[0x563fbec64d4b]
 
handler/handler0alter.cc:7786(ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x563fbe9894e2]
 
sql/handler.cc:5217(handler::ha_prepare_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x563fbe57de98]
 
sql/sql_table.cc:7372(mysql_inplace_alter_table(THD*, TABLE_LIST*, TABLE*, TABLE*, Alter_inplace_info*, MDL_request*, st_ddl_log_state*, TRIGGER_RENAME_PARAM*, Alter_table_ctx*))[0x563fbe2e8b11]
 
sql/sql_table.cc:10353(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool))[0x563fbe2f1aad]
 
sql/sql_alter.cc:552(Sql_cmd_alter_table::execute(THD*))[0x563fbe3a4351]
 
sql/sql_parse.cc:6000(mysql_execute_command(THD*, bool))[0x563fbe1f13f0]
 
sql/sql_parse.cc:8019(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x563fbe1f669f]
 
sql/sql_parse.cc:1898(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x563fbe1e5c0c]
 
sql/sql_parse.cc:1409(do_command(THD*, bool))[0x563fbe1e49bf]
 
sql/sql_connect.cc:1416(do_handle_one_connection(CONNECT*, bool))[0x563fbe399847]
 
sql/sql_connect.cc:1320(handle_one_connection)[0x563fbe3995c5]
 
perfschema/pfs.cc:2203(pfs_spawn_thread)[0x563fbe8a3f7f]
 
nptl/pthread_create.c:463(start_thread)[0x7f2ac10c56db]
 
x86_64/clone.S:97(clone)[0x7f2ac0dee61f]

Patch to repeat the issue:

diff --git a/storage/innobase/handler/handler0alter.cc b/storage/innobase/handler/handler0alter.cc
 
index 7c162b9af6a..d60c26868f7 100644
 
--- a/storage/innobase/handler/handler0alter.cc
 
+++ b/storage/innobase/handler/handler0alter.cc
 
@@ -11273,7 +11273,8 @@ ha_innobase::commit_inplace_alter_table(
 
        }
 
 
 
 
        DBUG_EXECUTE_IF("stats_lock_fail",
 
-                       error = DB_LOCK_WAIT_TIMEOUT;);
 
+                       error = DB_LOCK_WAIT_TIMEOUT;
 
+                       trx_rollback_for_mysql(trx););
 
 
        if (error == DB_SUCCESS) {
 
                error = lock_sys_tables(trx);

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