[MDEV-22788] SUMMARY: AddressSanitizer: heap-use-after-free storage/innobase/include/dict0dict.ic:1026 in dict_index_get_nth_field Created: 2020-06-03  Updated: 2023-04-27

Status: Confirmed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Locking, Storage Engine - InnoDB
Affects Version/s: 10.2.33, 10.3, 10.4, 10.5
Fix Version/s: 10.4, 10.5

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Vladislav Lesin
Resolution: Unresolved Votes: 0
Labels: ASAN, affects-tests, ddl, foreign-keys, not-10.6, online-ddl, race, rr-profile-analyzed

Attachments: File 001669.log    
Issue Links:
Duplicate
duplicates MDEV-18047 Crash in dict_foreign_qualify_index o... Confirmed
Relates
relates to MDEV-18259 ASAN heap-use-after-free or server cr... Closed
relates to MDEV-21175 Remove dict_table_t::n_foreign_key_ch... Closed
relates to MDEV-26554 Table-rebuilding DDL on parent table ... Closed

 Description    

RQG testing on
 
origin/10.2 50641db2d11ad8a2228f7938d851e52decb71a9b 2020-06-01T15:38:04+02:00
 
 
 
==73006==ERROR: AddressSanitizer: heap-use-after-free on address 0x617000276bb0 at pc 0x56316fa45e19 bp 0x46215c741180 sp 0x46215c741170
 
READ of size 20 at 0x617000276bb0 thread T34
 
    #0 0x56316fa45e18 in dict_index_get_nth_field storage/innobase/include/dict0dict.ic:1026
 
    #1 0x56316fa45f56 in dict_index_get_nth_col storage/innobase/include/dict0dict.ic:1079
 
    #2 0x56316fa73897 in dict_foreign_qualify_index(dict_table_t const*, char const**, char const**, unsigned long, dict_index_t const*, dict_index_t const*, bool, unsigned long, fkerr_t*, unsigned long*, dict_index_t**) storage/innobase/dict/dict0dict.cc:6662
 
    #3 0x56316fa5d99e in dict_foreign_find_index(dict_table_t const*, char const**, char const**, unsigned long, dict_index_t const*, bool, unsigned long, fkerr_t*, unsigned long*, dict_index_t**) storage/innobase/dict/dict0dict.cc:3148
 
    #4 0x56316f4943ec in innobase_update_foreign_try storage/innobase/handler/handler0alter.cc:7338
 
    #5 0x56316f4a2a2d in commit_try_norebuild(Alter_inplace_info*, ha_innobase_inplace_ctx*, TABLE*, TABLE const*, trx_t*, char const*) (/home/mleich/Server_bin/10.2_asan/bin/mysqld+0x1b55a2d)
 
    #6 0x56316f49905e in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) storage/innobase/handler/handler0alter.cc:8423
 
    #7 0x56316eeb9886 in handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) sql/handler.cc:4378
 
    #8 0x56316ea8679a in mysql_inplace_alter_table sql/sql_table.cc:7480
 
    #9 0x56316ea96323 in mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) sql/sql_table.cc:9615
 
    #10 0x56316ebe9080 in Sql_cmd_alter_table::execute(THD*) sql/sql_alter.cc:333
 
    #11 0x56316e851c05 in mysql_execute_command(THD*) sql/sql_parse.cc:5972
 
    #12 0x56316e85d65c in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) sql/sql_parse.cc:7741
 
    #13 0x56316e834308 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) sql/sql_parse.cc:1831
 
    #14 0x56316e830d2f in do_command(THD*) sql/sql_parse.cc:1385
 
    #15 0x56316ebd8f75 in do_handle_one_connection(CONNECT*) sql/sql_connect.cc:1336
 
    #16 0x56316ebd8832 in handle_one_connection sql/sql_connect.cc:1241
 
    #17 0x796d128366da in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
 
    #18 0x4d414f47e88e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x12188e)
 
...
 
SUMMARY: AddressSanitizer: heap-use-after-free storage/innobase/include/dict0dict.ic:1026 in dict_index_get_nth_field
 
...
 
Query (0x62b00012d228): ALTER TABLE `D` /* 100301 WAIT 1 */ ADD CONSTRAINT r FOREIGN KEY ( `col_int_nokey` ) REFERENCES `AA` (col_varchar_key) ON DELETE RESTRICT, ALGORITHM=INPLACE
 
...
 
Connection ID (thread ID): 18
 
Status: NOT_KILLED
 
 
 
RQG
 
-------
 
git clone https://github.com/mleich1/rqg --branch experimental RQG_mleich
 
origin/experimental 5c63068c24fa6d687422f4d26490b067ff6535e4 2020-05-28T13:50:30+02:00
 
 
 
perl rqg.pl \                        
--views \
 
--grammar=conf/mariadb/partitions_innodb.yy \
 
--redefine=conf/mariadb/alter_table.yy \
 
--redefine=conf/mariadb/instant_add.yy \
 
--redefine=conf/mariadb/modules/alter_table_columns.yy \
 
--redefine=conf/mariadb/sp.yy \
 
--redefine=conf/mariadb/bulk_insert.yy \
 
--redefine=conf/mariadb/modules/userstat.yy \
 
--redefine=conf/mariadb/modules/foreign_keys.yy \
 
--redefine=conf/mariadb/modules/locks.yy \
 
--redefine=conf/mariadb/modules/sql_mode.yy \
 
--redefine=conf/mariadb/versioning.yy \
 
--redefine=conf/mariadb/sequences.yy \
 
--redefine=conf/mariadb/modules/locks-10.4-extra.yy \
 
--mysqld=--innodb_use_native_aio=1 \
 
--mysqld=--innodb_stats_persistent=off \
 
--mysqld=--innodb_lock_schedule_algorithm=fcfs \
 
--mysqld=--loose-idle_write_transaction_timeout=0 \
 
--mysqld=--loose-idle_transaction_timeout=0 \
 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
 
--mysqld=--connect_timeout=60 \
 
--mysqld=--interactive_timeout=28800 \
 
--mysqld=--slave_net_timeout=60 \
 
--mysqld=--net_read_timeout=30 \
 
--mysqld=--net_write_timeout=60 \
 
--mysqld=--loose-table_lock_wait_timeout=50 \
 
--mysqld=--wait_timeout=28800 \
 
--mysqld=--lock-wait-timeout=86400 \
 
--mysqld=--innodb-lock-wait-timeout=50 \
 
--no-mask \
 
--queries=10000000 \
 
--seed=random \
 
--reporters=Backtrace \
 
--reporters=ErrorLog \
 
--reporters=Deadlock1 \
 
--validators=None \
 
--mysqld=--log_output=none \
 
--mysqld=--log-bin \
 
--mysqld=--log_bin_trust_function_creators=1 \
 
--mysqld=--loose-max-statement-time=30 \
 
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
--engine=InnoDB \
 
--restart_timeout=120 \
 
--duration=300 \
 
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
--threads=2 \
 
--mysqld=--innodb_page_size=8K \
 
--mysqld=--innodb-buffer-pool-size=8M \
 
--duration=300 \
 
--no_mask \
 
--workdir=<local settings> \
 
--vardir=<local settings> \
 
--mtr-build-thread=<local settings> \
 
--basedir1=<local settings> \
 
--script_debug=_nix_ \
 
--rr=Server \
 
--rr_options=--chaos



 Comments   
Comment by Marko Mäkelä [ 2020-07-28 ]

The memory was created on a table-rebuilding ALTER TABLE and freed on its rollback:

10.2 ba23e6d76fde4abdb6666e8d78af98ce6d2414e3 with git cherry-pick a1f899a8abb6bb0b046db28d6da9dd4b7fc3c8c4 (MDEV-23233 fix)

 
Thread 35 hit Breakpoint 4, dict_mem_index_create (table_name=0x60300007a0e0 "test/#sql-e4b0_12", index_name=0x61b0002b0408 "col_varchar_key", space=297, type=0, n_fields=4)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0mem.cc:734
 
(rr) when
 
Current event: 430447
 
(rr) bt
 
#0  dict_mem_index_create (table_name=0x60300007a0e0 "test/#sql-e4b0_12", index_name=0x61b0002b0408 "col_varchar_key", space=297, type=0, n_fields=4)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0mem.cc:734
 
#1  0x000055dc9d42ed77 in dict_index_build_internal_non_clust (table=table@entry=0x61800019f508, index=0x6170000bed08) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0dict.cc:2902
 
#2  0x000055dc9d4300b0 in dict_index_add_to_cache (table=0x61800019f508, index=@0x6160003b7a40: 0x6170000bed08, page_no=page_no@entry=4294967295, add_v=0x0)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0dict.cc:2270
 
#3  0x000055dc9d3fc399 in dict_create_index_step (thr=thr@entry=0x61a000497cb0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0crea.cc:1485
 
#4  0x000055dc9cf1fec8 in que_thr_step (thr=0x61a000497cb0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/que/que0que.cc:1052
 
#5  que_run_threads_low (thr=thr@entry=0x61a000497cb0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/que/que0que.cc:1104
 
#6  0x000055dc9cf21288 in que_run_threads (thr=thr@entry=0x61a000497cb0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/que/que0que.cc:1144
 
#7  0x000055dc9cfbb5da in row_merge_create_index_graph (trx=trx@entry=0x6e875fa7add0, table=table@entry=0x61800019f508, index=@0x18242b4c1d30: 0x6170000bed08, add_v=add_v@entry=0x0)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/row/row0merge.cc:4339
 
#8  0x000055dc9cfbbd63 in row_merge_create_index (trx=<optimized out>, table=0x61800019f508, index_def=index_def@entry=0x619001d446c8, add_v=add_v@entry=0x0)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/row/row0merge.cc:4410
 
#9  0x000055dc9cd5082e in prepare_inplace_alter_table_dict (ha_alter_info=ha_alter_info@entry=0x18242b4c3050, altered_table=altered_table@entry=0x61e000297088, old_table=<optimized out>, 
    table_name=<optimized out>, flags=<optimized out>, flags2=<optimized out>, fts_doc_id_col=<optimized out>, add_fts_doc_id=<optimized out>, add_fts_doc_id_idx=<optimized out>)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/handler/handler0alter.cc:4837
 
#10 0x000055dc9cd6114b in ha_innobase::prepare_inplace_alter_table (this=0x61c0000be0a8, altered_table=<optimized out>, ha_alter_info=0x18242b4c3050)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/handler/handler0alter.cc:6044
 
#11 0x000055dc9c6d1cbd in handler::ha_prepare_inplace_alter_table (this=0x61c0000be0a8, altered_table=altered_table@entry=0x61e000297088, ha_alter_info=ha_alter_info@entry=0x18242b4c3050)
 
    at /home/mleich/bb-10.2-MDEV-23233/sql/handler.cc:4358
 
#12 0x000055dc9c28222d in mysql_inplace_alter_table (thd=thd@entry=0x62a0001fe208, table_list=0x62b00012d3f0, table=table@entry=0x61e0000cb488, altered_table=altered_table@entry=0x61e000297088, 
    ha_alter_info=ha_alter_info@entry=0x18242b4c3050, inplace_supported=<optimized out>, target_mdl_request=<optimized out>, alter_ctx=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_table.cc:7420
 
#13 0x000055dc9c2a0533 in mysql_alter_table (thd=thd@entry=0x62a0001fe208, new_db=<optimized out>, new_name=<optimized out>, create_info=create_info@entry=0x18242b4c4c10, table_list=<optimized out>, 
    table_list@entry=0x62b00012d3f0, alter_info=alter_info@entry=0x18242b4c4b30, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>)
 
    at /home/mleich/bb-10.2-MDEV-23233/sql/sql_table.cc:9622
 
#14 0x000055dc9c3e7551 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62a0001fe208) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_alter.cc:333
 
#15 0x000055dc9c066c0f in mysql_execute_command (thd=thd@entry=0x62a0001fe208) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:5964
 
#16 0x000055dc9c06a82f in mysql_parse (thd=thd@entry=0x62a0001fe208, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x18242b4c73d0, is_com_multi=is_com_multi@entry=false, 
    is_next_command=is_next_command@entry=false) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:7733
 
#17 0x000055dc9c072ffa in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62a0001fe208, 
    packet=packet@entry=0x62d000870409 "ALTER IGNORE TABLE `C` /*!100301 */ ADD IF NOT EXISTS z BIT DEFAULT 0  /* E_R Thread1 QNO 558 CON_ID 18 */ ", packet_length=packet_length@entry=107, 
    is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:1823
 
…
 
(rr) continue
 
Thread 35 hit Hardware access (read/write) watchpoint 3: *$6
 
 
 
Old value = 0 '\000'
 
New value = -3 '\375'
 
__memset_avx2_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:177
 
177	../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: No such file or directory.
 
1: x/i $pc
 
=> 0x5685671d4200 <__memset_avx2_unaligned_erms+64>:	vmovdqu %ymm0,0x20(%rdi)
 
(rr) bt
 
#0  __memset_avx2_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:177
 
#1  0x000055dc9f8395ef in ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.4
 
#2  0x000055dc9f8f1773 in free () from /usr/lib/x86_64-linux-gnu/libasan.so.4
 
#3  0x000055dc9ce63ee9 in mem_heap_block_free (heap=heap@entry=0x61100026b3c0, block=block@entry=0x617000253b00) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/mem/mem0mem.cc:428
 
#4  0x000055dc9d46bc06 in mem_heap_free (heap=0x61100026b3c0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/include/mem0mem.ic:416
 
#5  dict_mem_index_free (index=index@entry=0x617000253b88) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0mem.cc:1081
 
#6  0x000055dc9d4285d2 in dict_index_remove_from_cache_low (table=table@entry=0x618000216d08, index=0x617000253b88, lru_evict=lru_evict@entry=0)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0dict.cc:2420
 
#7  0x000055dc9d428da1 in dict_table_remove_from_cache_low (table=0x618000216d08, lru_evict=lru_evict@entry=0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0dict.cc:2089
 
#8  0x000055dc9d429bec in dict_table_remove_from_cache (table=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0dict.cc:2154
 
#9  0x000055dc9cffc2b5 in row_drop_table_from_cache (trx=0x6e875fa7add0, table=<optimized out>, tablename=0x6130002385c8 "test/#sql-ib313")
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/row/row0mysql.cc:3223
 
#10 row_drop_table_for_mysql (name=<optimized out>, trx=0x6e875fa7add0, sqlcom=sqlcom@entry=SQLCOM_DROP_TABLE, create_failed=create_failed@entry=false, nonatomic=<optimized out>, nonatomic@entry=false)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/row/row0mysql.cc:3728
 
#11 0x000055dc9cfb8b5d in row_merge_drop_table (trx=<optimized out>, table=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/row/row0merge.cc:4472
 
#12 0x000055dc9cd6d536 in ha_innobase::commit_inplace_alter_table (this=<optimized out>, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>)
 
…
 
#19 0x000055dc9c072ffa in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62a0001fe208, 
    packet=packet@entry=0x62d000870409 "ALTER IGNORE TABLE `C` /*!100301 */ ADD IF NOT EXISTS z BIT DEFAULT 0  /* E_R Thread1 QNO 558 CON_ID 18 */ ", packet_length=packet_length@entry=107, 
    is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:1823
 
…
 
(rr) when
 
Current event: 437083

This seems to be a table-rebuilding ALTER TABLE that was rolled back. The invalid access comes from another thread, for a FOREIGN KEY check:

Thread 3 hit Hardware access (read/write) watchpoint 3: *$6
 
 
 
Value = -3 '\375'
 
0x000055dc9d403bf0 in dict_index_get_nth_field (index=0x617000253b88, pos=0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/include/dict0dict.ic:1028
 
1028		ut_ad(pos < index->n_def);
 
1: x/i $pc
 
=> 0x55dc9d403bf0 <dict_index_get_nth_field(dict_index_t const*, ulint)+22>:	lea    0x3b(%rdi),%rax
 
(rr) bt
 
#0  0x000055dc9d403bf0 in dict_index_get_nth_field (index=0x617000253b88, pos=0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/include/dict0dict.ic:1028
 
#1  0x000055dc9d411192 in dict_index_get_nth_col (pos=0, index=0x617000253b88) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/include/dict0dict.ic:1081
 
#2  dict_foreign_qualify_index (table=table@entry=0x618000096508, col_names=col_names@entry=0x0, columns=columns@entry=0x616000071ba0, n_cols=n_cols@entry=1, index=index@entry=0x61700023fd08, 
    types_idx=types_idx@entry=0x617000253b88, check_charsets=true, check_null=0, error=0x0, err_col_no=0x0, err_index=0x0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0dict.cc:6663
 
#3  0x000055dc9d41190c in dict_foreign_find_index (table=0x618000096508, col_names=0x0, columns=0x616000071ba0, n_cols=1, types_idx=0x617000253b88, check_charsets=check_charsets@entry=true, check_null=0, 
    error=0x0, err_col_no=0x0, err_index=0x0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/dict/dict0dict.cc:3148
 
#4  0x000055dc9cd4235b in innobase_update_foreign_try (ctx=ctx@entry=0x62b00016fdf8, trx=trx@entry=0x6e875fa7d020, table_name=table_name@entry=0x61a0000e5dbd "DD")
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/handler/handler0alter.cc:7338
 
#5  0x000055dc9cd68335 in commit_try_norebuild (table_name=0x61a0000e5dbd "DD", trx=0x6e875fa7d020, old_table=0x61e000151888, altered_table=0x61e0000c9088, ctx=0x62b00016fdf8, ha_alter_info=0x40477294d050)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/handler/handler0alter.cc:7729
 
#6  ha_innobase::commit_inplace_alter_table (this=<optimized out>, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/handler/handler0alter.cc:8424
 
#7  0x000055dc9c6d1e0a in handler::ha_commit_inplace_alter_table (this=0x61c00015f8a8, altered_table=altered_table@entry=0x61e0000c9088, ha_alter_info=ha_alter_info@entry=0x40477294d050, 
    commit=commit@entry=true) at /home/mleich/bb-10.2-MDEV-23233/sql/handler.cc:4378
 
#8  0x000055dc9c28261f in mysql_inplace_alter_table (thd=thd@entry=0x62a00023a208, table_list=0x62b00016c470, table=table@entry=0x61e000151888, altered_table=altered_table@entry=0x61e0000c9088, 
    ha_alter_info=ha_alter_info@entry=0x40477294d050, inplace_supported=<optimized out>, target_mdl_request=<optimized out>, alter_ctx=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_table.cc:7480
 
#9  0x000055dc9c2a0533 in mysql_alter_table (thd=thd@entry=0x62a00023a208, new_db=<optimized out>, new_name=<optimized out>, create_info=create_info@entry=0x40477294ec10, table_list=<optimized out>, 
    table_list@entry=0x62b00016c470, alter_info=alter_info@entry=0x40477294eb30, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>)
 
    at /home/mleich/bb-10.2-MDEV-23233/sql/sql_table.cc:9622
 
#10 0x000055dc9c3e7551 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62a00023a208) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_alter.cc:333
 
#11 0x000055dc9c066c0f in mysql_execute_command (thd=thd@entry=0x62a00023a208) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:5964
 
#12 0x000055dc9c06a82f in mysql_parse (thd=thd@entry=0x62a00023a208, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x4047729513d0, is_com_multi=is_com_multi@entry=false, 
    is_next_command=is_next_command@entry=false) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:7733
 
#13 0x000055dc9c072ffa in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62a00023a208, 
    packet=packet@entry=0x62d000852409 "ALTER ONLINE IGNORE TABLE `DD` /*!100301 NOWAIT */ ADD FOREIGN KEY ( `col_int_nokey` ) REFERENCES `C` (col_varchar_key) ON UPDATE CASCADE  /* E_R Thread8 QNO 608 CON_ID 23 */ ", packet_length=packet_length@entry=175, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:1823
 
…
 
(rr) when
 
Current event: 438842

At the time of the freeing, that other thread was already being executed inside InnoDB. We seem to be missing necessary MDL protection between the two ALTER TABLE, with regard to the FOREIGN KEY constraints:

(rr) when
 
Current event: 437083
 
(rr) thread 3
 
[Switching to thread 3 (Thread 58544.66078)]
 
#0  0x0000000070000002 in ?? ()
 
(rr) bt
 
#0  0x0000000070000002 in ?? ()
 
#1  0x0000568566bf5b27 in _raw_syscall () at /home/roc/rr/rr/src/preload/raw_syscall.S:120
 
#2  0x0000568566bf0e7e in traced_raw_syscall (call=<optimized out>) at /home/roc/rr/rr/src/preload/syscallbuf.c:229
 
#3  0x0000568566bf4682 in sys_futex (call=<optimized out>) at /home/roc/rr/rr/src/preload/syscallbuf.c:1355
 
#4  syscall_hook_internal (call=0x7f2de9ec1fa0) at /home/roc/rr/rr/src/preload/syscallbuf.c:2861
 
#5  syscall_hook (call=0x7f2de9ec1fa0) at /home/roc/rr/rr/src/preload/syscallbuf.c:2987
 
#6  0x0000568566bf0d5a in _syscall_hook_trampoline () at /home/roc/rr/rr/src/preload/syscall_hook.S:282
 
#7  0x0000568566bf0d8a in __morestack () at /home/roc/rr/rr/src/preload/syscall_hook.S:417
 
#8  0x0000568566bf0da5 in _syscall_hook_trampoline_48_3d_00_f0_ff_ff () at /home/roc/rr/rr/src/preload/syscall_hook.S:428
 
#9  0x0000597231dff9f9 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x60b001b86ea8) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
 
#10 __pthread_cond_wait_common (abstime=0x0, mutex=0x60b001b86e58, cond=0x60b001b86e80) at pthread_cond_wait.c:502
 
#11 __pthread_cond_wait (cond=cond@entry=0x60b001b86e80, mutex=mutex@entry=0x60b001b86e58) at pthread_cond_wait.c:655
 
#12 0x000055dc9ceac723 in os_event::wait (this=0x60b001b86e40) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/os/os0event.cc:158
 
#13 os_event::wait_low (this=0x60b001b86e40, reset_sig_count=250) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/os/os0event.cc:325
 
#14 0x000055dc9ceacda3 in os_event_wait_low (event=<optimized out>, reset_sig_count=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/os/os0event.cc:507
 
#15 0x000055dc9d1425a0 in sync_array_wait_event (arr=arr@entry=0x611000001e40, cell=@0x40477294c810: 0x701c11f65a40) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/sync/sync0arr.cc:471
 
#16 0x000055dc9cd55d59 in TTASEventMutex<GenericPolicy>::enter (line=<optimized out>, filename=<optimized out>, max_delay=<optimized out>, max_spins=<optimized out>, this=<optimized out>)
 
    at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/include/ib0mutex.h:516
 
#17 PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (line=6312, name=0x55dc9df292c0 "/home/mleich/bb-10.2-MDEV-23233/storage/innobase/handler/handler0alter.cc", n_delay=<optimized out>, 
    n_spins=<optimized out>, this=0x611000003ec0) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/include/ib0mutex.h:637
 
#18 ha_innobase::inplace_alter_table (this=0x61c00015f8a8, altered_table=<optimized out>, ha_alter_info=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/storage/innobase/handler/handler0alter.cc:6312
 
#19 0x000055dc9c2824a4 in handler::ha_inplace_alter_table (ha_alter_info=0x40477294d050, altered_table=0x61e0000c9088, this=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/sql/handler.h:3790
 
#20 mysql_inplace_alter_table (thd=thd@entry=0x62a00023a208, table_list=0x62b00016c470, table=table@entry=0x61e000151888, altered_table=altered_table@entry=0x61e0000c9088, 
    ha_alter_info=ha_alter_info@entry=0x40477294d050, inplace_supported=<optimized out>, target_mdl_request=<optimized out>, alter_ctx=<optimized out>) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_table.cc:7453
 
#21 0x000055dc9c2a0533 in mysql_alter_table (thd=thd@entry=0x62a00023a208, new_db=<optimized out>, new_name=<optimized out>, create_info=create_info@entry=0x40477294ec10, table_list=<optimized out>, 
    table_list@entry=0x62b00016c470, alter_info=alter_info@entry=0x40477294eb30, order_num=<optimized out>, order=<optimized out>, ignore=<optimized out>)
 
    at /home/mleich/bb-10.2-MDEV-23233/sql/sql_table.cc:9622
 
#22 0x000055dc9c3e7551 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x62a00023a208) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_alter.cc:333
 
#23 0x000055dc9c066c0f in mysql_execute_command (thd=thd@entry=0x62a00023a208) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:5964
 
#24 0x000055dc9c06a82f in mysql_parse (thd=thd@entry=0x62a00023a208, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x4047729513d0, is_com_multi=is_com_multi@entry=false, 
    is_next_command=is_next_command@entry=false) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:7733
 
#25 0x000055dc9c072ffa in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x62a00023a208, 
    packet=packet@entry=0x62d000852409 "ALTER ONLINE IGNORE TABLE `DD` /*!100301 NOWAIT */ ADD FOREIGN KEY ( `col_int_nokey` ) REFERENCES `C` (col_varchar_key) ON UPDATE CASCADE  /* E_R Thread8 QNO 608 CON_ID 23 */ ", packet_length=packet_length@entry=175, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /home/mleich/bb-10.2-MDEV-23233/sql/sql_parse.cc:1823

If we had sufficient MDL in place, the two ALTER TABLE would block each other.

Comment by Marko Mäkelä [ 2020-08-07 ]

I believe that a proper fix of MDEV-21175 should add the necessary MDL protection.

Comment by Marko Mäkelä [ 2022-02-21 ]

MDEV-21175 and the follow-up fix (work-around for inadequate metadata locking) MDEV-26554 were implemented in 10.6.

For 10.6, all DDL was heavily refactored in order to implement crash-safe DDL operations. The substantial changes include MDEV-24258, MDEV-25506, and MDEV-25919. For older versions, we might want a different type of fix, or we might say that this is not feasible to fix due to the risk that is involved with the extensive changes.

Comment by Marko Mäkelä [ 2022-11-08 ]

Possibly, an applicable part of the fix of MDEV-29504 in 10.6 might fix this trouble in older major versions. Clearly, ha_innobase::referenced_by_foreign_key() will need some synchronization with dict_sys.

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