[MDEV-28855] SEGV around dict_free_vc_templ during DROP INDEX Created: 2022-06-15  Updated: 2023-06-30  Resolved: 2023-03-29

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Virtual Columns
Affects Version/s: 10.3.36, 10.6.9
Fix Version/s: 10.11.2, 10.3.38, 10.4.28, 10.5.19, 10.6.12, 10.7.8, 10.8.7, 10.9.5, 10.10.3

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: rr-profile

Attachments: File serg.tgz     File table_stress_innodb_nocopy2.yy    
Issue Links:
Relates
relates to MDEV-31594 SEGV during DROP generated column Open

 Description    

origin/10.6 6c82ab4f726b83f09646c22afddd4c102e60607b 2022-06-14T15:33:11+03:00
 
# 2022-06-15T12:12:17 [3188740] | [rr 3191641 910722]2022-06-15 12:08:51 200 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
# 2022-06-15T12:12:17 [3188740] | [rr 3191641 910750]2022-06-15 12:08:51 200 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
# 2022-06-15T12:12:17 [3188740] | [rr 3191641 910754]2022-06-15 12:08:51 200 [Note] InnoDB: Online DDL : Applying log to index
 
# 2022-06-15T12:12:17 [3188740] | [rr 3191641 912270]220615 12:08:51 [rr 3191641 912273][ERROR] mysqld got signal 11 ;
 
 
 
Thread 2 received signal SIGSEGV, Segmentation fault.
 
[Switching to Thread 3191641.3192456]
 
0x000055db215d865d in dict_free_vc_templ (vc_templ=0x0) at /data/Server/10.6R/storage/innobase/include/dict0dict.inl:1184
 
1184            UT_DELETE_ARRAY(vc_templ->default_rec);
 
(rr) bt
 
#0  0x000055db215d865d in dict_free_vc_templ (vc_templ=0x0) at /data/Server/10.6R/storage/innobase/include/dict0dict.inl:1184
 
#1  0x000055db216106d4 in ha_innobase::prepare_inplace_alter_table (this=0x61d000a758b8, altered_table=0x12eb5c66b290, ha_alter_info=0x12eb5c66ab90) at /data/Server/10.6R/storage/innobase/handler/handler0alter.cc:8215
 
#2  0x000055db20c7625a in handler::ha_prepare_inplace_alter_table (this=0x61d000a758b8, altered_table=0x12eb5c66b290, ha_alter_info=0x12eb5c66ab90) at /data/Server/10.6R/sql/handler.cc:5199
 
#3  0x000055db206edea2 in mysql_inplace_alter_table (thd=0x62b00009a218, table_list=0x62b0000a1418, table=0x6190003aed98, altered_table=0x12eb5c66b290, ha_alter_info=0x12eb5c66ab90, target_mdl_request=0x12eb5c66ac90, 
    ddl_log_state=0x12eb5c66a9b0, trigger_param=0x12eb5c66b700, alter_ctx=0x12eb5c66c1a0) at /data/Server/10.6R/sql/sql_table.cc:7359
 
#4  0x000055db207025ca in mysql_alter_table (thd=0x62b00009a218, new_db=0x62b00009ec18, new_name=0x62b00009f030, create_info=0x12eb5c66d650, table_list=0x62b0000a1418, alter_info=0x12eb5c66d520, order_num=0, order=0x0, 
    ignore=false, if_exists=false) at /data/Server/10.6R/sql/sql_table.cc:10278
 
#5  0x000055db20891700 in Sql_cmd_alter_table::execute (this=0x62b0000a1bf0, thd=0x62b00009a218) at /data/Server/10.6R/sql/sql_alter.cc:542
 
#6  0x000055db20492589 in mysql_execute_command (thd=0x62b00009a218, is_called_from_prepared_stmt=false) at /data/Server/10.6R/sql/sql_parse.cc:5996
 
#7  0x000055db2049e956 in mysql_parse (thd=0x62b00009a218, rawbuf=0x62b0000a1238 "ALTER TABLE t1 DROP KEY `Marvão_idx1`, DROP INDEX `uidx2`, ALGORITHM = NOCOPY, LOCK = DEFAULT  /* E_R Thread2 QNO 3070 CON_ID 210 */", 
    length=133, parser_state=0x12eb5c66eb20) at /data/Server/10.6R/sql/sql_parse.cc:8029
 
#8  0x000055db20476d64 in dispatch_command (command=COM_QUERY, thd=0x62b00009a218, 
    packet=0x629000505219 " ALTER TABLE t1 DROP KEY `Marvão_idx1`, DROP INDEX `uidx2`, ALGORITHM = NOCOPY, LOCK = DEFAULT  /* E_R Thread2 QNO 3070 CON_ID 210 */ ", packet_length=135, blocking=true)
 
    at /data/Server/10.6R/sql/sql_parse.cc:1896
 
#9  0x000055db204741ab in do_command (thd=0x62b00009a218, blocking=true) at /data/Server/10.6R/sql/sql_parse.cc:1409
 
#10 0x000055db20877b73 in do_handle_one_connection (connect=0x608000040fb8, put_in_cache=true) at /data/Server/10.6R/sql/sql_connect.cc:1418
 
#11 0x000055db208773ff in handle_one_connection (arg=0x608000002eb8) at /data/Server/10.6R/sql/sql_connect.cc:1312
 
#12 0x00007fc54a654609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#13 0x00007fc54a790293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
(rr)
 
 
 
pluto:/data/results/1655290115/TBR-1318
 
_RR_TRACE_DIR="./1/rr" rr replay --mark-stdio
 
 
 
# rqg.pl  : Version 4.0.6 (2022-05)
 
#
 
# $RQG_HOME/rqg.pl \
 
# --grammar=conf/mariadb/table_stress_innodb_nocopy2.yy \
 
# --gendata=conf/mariadb/table_stress.zz \
 
# --gendata_sql=conf/mariadb/table_stress.sql \
 
# --reporters=CrashRecovery1 \
 
# --mysqld=--loose-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_trust_function_creators=1 \
 
# --mysqld=--loose-debug_assert_on_not_freed_memory=0 \
 
# --engine=InnoDB \
 
# --restart_timeout=240 \
 
# --mysqld=--plugin-load-add=file_key_management.so \
 
# --mysqld=--loose-file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
 
# --mysqld=--plugin-load-add=provider_lzo.so \
 
# --mysqld=--plugin-load-add=provider_bzip2.so \
 
# --mysqld=--plugin-load-add=provider_lzma.so \
 
# --mysqld=--plugin-load-add=provider_snappy.so \
 
# --mysqld=--plugin-load-add=provider_lz4.so \
 
# --mysqld=--loose-innodb_fatal_semaphore_wait_threshold=300 \
 
# --duration=300 \
 
# --mysqld=--loose-innodb_read_only_compressed=OFF \
 
# --mysqld=--innodb_stats_persistent=off \
 
# --mysqld=--innodb_adaptive_hash_index=on \
 
# --mysqld=--loose-innodb_evict_tables_on_commit_debug=off \
 
# --mysqld=--loose-max-statement-time=30 \
 
# --threads=9 \
 
# --mysqld=--innodb-use-native-aio=0 \
 
# --mysqld=--loose-gdb \
 
# --mysqld=--loose-debug-gdb \
 
# --rr=Extended \
 
# --rr_options=--chaos --wait \
 
# --mysqld=--innodb_undo_tablespaces=3 \
 
# --mysqld=--innodb_undo_log_truncate=ON \
 
# --mysqld=--loose_innodb_change_buffering=changes \
 
# --mysqld=--innodb_rollback_on_timeout=OFF \
 
# --vardir_type=fast \
 
# --mysqld=--innodb_page_size=32K \
 
# --mysqld=--innodb-buffer-pool-size=24M \
 
# --no_mask \
 
# <local settings>



 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2022-06-16 ] 

--source include/have_innodb.inc
 
create table t1(f1 int not null, f2 char(100), f3 char(100) as (f2),
 
                index idx(f3), index idx_1(f3, f1))engine=innodb;
 
insert into t1(f1, f2) values(1, repeat('a', 10));
 
SET DEBUG_DBUG="+d,stats_lock_fail";
 
--error 1030
 
alter table t1 drop index idx, algorithm=inplace;
 
SET DEBUG_DBUG="-d,stats_lock_fail";
 
alter table t1 drop index idx_1, algorithm=inplace;
 
show create table t1;
 
drop table t1;

Issue is almost similar to above test case. InnoDB DDL clears vc_templ and fails due to time out. Next alter here does ha_innobase::open() and reconstruct vc_templ
The following code does clear the vc_templ in ha_innobase::prepare_inplace_alter_table

                if (!(ha_alter_info->handler_flags & INNOBASE_ALTER_DATA)
 
                    && alter_templ_needs_rebuild(altered_table, ha_alter_info,
 
                                                 ctx->new_table)
 
                    && ctx->new_table->n_v_cols > 0) {
 
                        /* Changing maria record structure may end up here only
 
                        if virtual columns were altered. In this case, however,
 
                        vc_templ should be rebuilt. Since we don't actually
 
                        change any stored data, we can just dispose vc_templ;
 
                        it will be recreated on next ha_innobase::open(). */
 
 
 
                        DBUG_ASSERT(ctx->new_table == ctx->old_table);
 
 
 
                        dict_free_vc_templ(ctx->new_table->vc_templ);
 
                        UT_DELETE(ctx->new_table->vc_templ);
 
 
 
                        ctx->new_table->vc_templ = NULL;
 
                }

But the next alter doesn't call ha_innobase::open at all.

Comment by Alice Sherepa [ 2022-07-15 ]

I'm getting smth related on 10.10:

220715 14:09:41 [ERROR] mysqld got signal 11 ;
 
 
 
Server version: 10.10.0-MariaDB-log
 
 
 
sql/signal_handler.cc:236(handle_fatal_signal)[0x557e12431165]
 
include/dict0dict.inl:1182(dict_free_vc_templ)[0x557e126eeefa]
 
sql/sql_table.cc:7614(mysql_inplace_alter_table)[0x557e122b0fc6]
 
sql/sql_parse.cc:5596(mysql_execute_command(THD*, bool))[0x557e1220c05a]
 
sql/sql_parse.cc:8053(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x557e121fe3fc]
 
sql/sql_parse.cc:1896(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool))[0x557e12208d1c]
 
sql/sql_parse.cc:1407(do_command(THD*, bool))[0x557e1220a3c6]
 
sql/sql_connect.cc:1418(do_handle_one_connection(CONNECT*, bool))[0x557e1230fd9f]
 
sql/sql_connect.cc:1312(handle_one_connection)[0x557e123100dd]
 
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x557e126367d5]
 
nptl/pthread_create.c:487(start_thread)[0x7fb946abafa3]
 
x86_64/clone.S:97(clone)[0x7fb9466c5eff]
 
 
 
Query (0x7fb880010930): DROP INDEX IF EXISTS b ON ind_constr_t4

Comment by Daniel Black [ 2022-10-19 ]

Same in mtr test gcol.innodb_virtual_basic

10.3-3a62ff7e8980239a39e85393c6a797bb7acf97ed

 
gcol.innodb_virtual_basic 'innodb'       w10 [ fail ]
 
        Test ended at 2022-10-19 09:37:21
 
 
 
CURRENT_TEST: gcol.innodb_virtual_basic
 
mysqltest: At line 329: query 'DROP INDEX idx ON t' failed: 2013: Lost connection to MySQL server during query
 
 
 
[Thread debugging using libthread_db enabled]
 
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
 
Core was generated by `/home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/mysqld --defaults-'.
 
Program terminated with signal SIGSEGV, Segmentation fault.
 
#0  0x00007f3ad8bf6f08 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0
 
[Current thread is 1 (Thread 0x7f3ad1a69700 (LWP 3375067))]
 
#0  0x00007f3ad8bf6f08 in pthread_kill () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#1  0x000055828c2490ee in my_write_core (sig=<optimized out>) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/mysys/stacktrace.c:386
 
#2  0x000055828bcc8ae8 in handle_fatal_signal (sig=11) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/signal_handler.cc:365
 
#3  <signal handler called>
 
#4  0x00007f3ad8a90870 in free () from /lib/x86_64-linux-gnu/libc.so.6
 
#5  0x000055828c071f33 in dict_free_vc_templ (vc_templ=0x7f3aa001dbd0) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/storage/innobase/include/dict0dict.inl:1417
 
#6  dict_table_remove_from_cache_low (table=0x7f3a78192dc0, lru_evict=<optimized out>) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/storage/innobase/dict/dict0dict.cc:1872
 
#7  0x000055828beb4b2c in innobase_reload_table (table_name=..., table=0x7f3a78192dc0, thd=0x7f3a78000d90) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/storage/innobase/handler/handler0alter.cc:8886
 
#8  ha_innobase::commit_inplace_alter_table (this=0x7f3a9000b978, altered_table=<optimized out>, ha_alter_info=<optimized out>, commit=<optimized out>) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/storage/innobase/handler/handler0alter.cc:10002
 
#9  0x000055828bb45d29 in mysql_inplace_alter_table (thd=0x7f3a78000d90, table_list=0x7f3a78012c00, table=0x7f3a9000a2a0, altered_table=0x7f3a78199450, ha_alter_info=0x7f3ad1a659c0, alter_ctx=0x7f3ad1a66230, target_mdl_request=<optimized out>) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_table.cc:7821
 
#10 0x000055828bb52a73 in mysql_alter_table (thd=thd@entry=0x7f3a78000d90, new_db=new_db@entry=0x7f3a78012c18, new_name=new_name@entry=0x7f3a78012c28, create_info=create_info@entry=0x7f3ad1a66e40, table_list=<optimized out>, table_list@entry=0x7f3a78012c00, alter_info=alter_info@entry=0x7f3ad1a66d80, order_num=0, order=0x0, ignore=false) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_table.cc:10159
 
#11 0x000055828baa91f9 in mysql_execute_command (thd=<optimized out>) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_parse.cc:4148
 
#12 0x000055828bab0b4a in mysql_parse (thd=0x7f3a78000d90, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_parse.cc:7855
 
#13 0x000055828bab32cd in dispatch_command (command=COM_QUERY, thd=0x7f3a78000d90, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_class.h:1153
 
#14 0x000055828bab53ac in do_command (thd=0x7f3a78000d90) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_parse.cc:1398
 
#15 0x000055828bbaae44 in do_handle_one_connection (connect=connect@entry=0x55828e803ca0) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_connect.cc:1403
 
#16 0x000055828bbab066 in handle_one_connection (arg=arg@entry=0x55828e803ca0) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/sql/sql_connect.cc:1308
 
#17 0x000055828c1fd071 in pfs_spawn_thread (arg=0x55828e7e6c70) at /home/buildbot/maria-slave/fulltest-debug-big-only/build/storage/perfschema/pfs.cc:1869
 
#18 0x00007f3ad8bee609 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
 
#19 0x00007f3ad8b15293 in clone () from /lib/x86_64-linux-gnu/libc.so.6


 

Comment by Sergei Golubchik [ 2022-11-02 ]

https://github.com/MariaDB/server/commit/905e6a7d83a40629587387b074a78c73f2242362
and
https://github.com/MariaDB/server/commit/363e45b383ed2bd397ad467ade87f2f1fd6a70a9

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

serg, both changes look rather reasonable to me.

To https://github.com/MariaDB/server/commit/363e45b383ed2bd397ad467ade87f2f1fd6a70a9 I posted a comment, suggesting to use a common pattern for allocating all dict_table_t::vc_templ. Actually, it could be safest to both allocate and initialize the buffer while holding dict_sys locked, to prevent any race condition between purge and ha_innobase::open(). We do not get any protection from MDL in these cases. InnoDB itself must guard against race conditions between the "first open" and concurrent "subsequent opens".

mleich, please test the branch.

Comment by Matthias Leich [ 2022-11-02 ] 

origin/bb-10.3-serg f39de95456e3cec4d835e35856207e6169bf89d6 2022-11-02T13:11:48+01:00
 
# 2022-11-02T06:33:57 [3952701] Thread 1 (Thread 0x7fe950539640 (LWP 3955704)):
 
# 2022-11-02T06:33:57 [3952701] #0  __pthread_kill_implementation (no_tid=0, signo=11, threadid=140640051762752) at ./nptl/pthread_kill.c:44
 
# 2022-11-02T06:33:57 [3952701] #1  __pthread_kill_internal (signo=11, threadid=140640051762752) at ./nptl/pthread_kill.c:78
 
# 2022-11-02T06:33:57 [3952701] #2  __GI___pthread_kill (threadid=140640051762752, signo=11) at ./nptl/pthread_kill.c:89
 
# 2022-11-02T06:33:57 [3952701] #3  0x00005630660d73a6 in my_write_core (sig=11) at /data/Server/bb-10.3-serg/mysys/stacktrace.c:386
 
# 2022-11-02T06:33:57 [3952701] #4  0x0000563065922b34 in handle_fatal_signal (sig=11) at /data/Server/bb-10.3-serg/sql/signal_handler.cc:365
 
# 2022-11-02T06:33:57 [3952701] #5  <signal handler called>
 
# 2022-11-02T06:33:57 [3952701] #6  dict_free_vc_templ (vc_templ=0x0) at /data/Server/bb-10.3-serg/storage/innobase/include/dict0dict.inl:1417
 
# 2022-11-02T06:33:57 [3952701] #7  0x0000563065ba9043 in ha_innobase::prepare_inplace_alter_table (this=<optimized out>, altered_table=0x7fe8d40bf758, ha_alter_info=0x7fe950536120) at /data/Server/bb-10.3-serg/storage/innobase/handler/handler0alter.cc:6903
 
# 2022-11-02T06:33:57 [3952701] #8  0x000056306592f72c in handler::ha_prepare_inplace_alter_table (this=0x7fe8d80a52d0, altered_table=altered_table@entry=0x7fe8d40bf758, ha_alter_info=ha_alter_info@entry=0x7fe950536120) at /data/Server/bb-10.3-serg/sql/handler.cc:4598
 
# 2022-11-02T06:33:57 [3952701] #9  0x0000563065764738 in mysql_inplace_alter_table (thd=thd@entry=0x7fe8d4000d38, table_list=0x7fe8d4010b80, table=table@entry=0x7fe8d80b8068, altered_table=altered_table@entry=0x7fe8d40bf758, ha_alter_info=ha_alter_info@entry=0x7fe950536120, target_mdl_request=target_mdl_request@entry=0x7fe9505362c0, alter_ctx=0x7fe950536a90) at /data/Server/bb-10.3-serg/sql/sql_table.cc:7737
 
# 2022-11-02T06:33:57 [3952701] #10 0x000056306576fbb1 in mysql_alter_table (thd=thd@entry=0x7fe8d4000d38, new_db=new_db@entry=0x7fe8d40052b0, new_name=new_name@entry=0x7fe8d4005698, create_info=create_info@entry=0x7fe950537670, table_list=<optimized out>, table_list@entry=0x7fe8d4010b80, alter_info=alter_info@entry=0x7fe9505375b0, order_num=0, order=0x0, ignore=false) at /data/Server/bb-10.3-serg/sql/sql_table.cc:10159
 
# 2022-11-02T06:33:57 [3952701] #11 0x00005630657de29d in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7fe8d4000d38) at /data/Server/bb-10.3-serg/sql/sql_alter.cc:512
 
# 2022-11-02T06:33:57 [3952701] #12 0x00005630656b49f9 in mysql_execute_command (thd=thd@entry=0x7fe8d4000d38) at /data/Server/bb-10.3-serg/sql/sql_parse.cc:6076
 
# 2022-11-02T06:33:57 [3952701] #13 0x00005630656b6310 in mysql_parse (thd=thd@entry=0x7fe8d4000d38, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7fe950538560, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/Server/bb-10.3-serg/sql/sql_parse.cc:7855
 
# 2022-11-02T06:33:57 [3952701] #14 0x00005630656b84c3 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7fe8d4000d38, packet=packet@entry=0x7fe8d4095b79 " ALTER TABLE t5 DROP INDEX `Marv\303\243o_idx1`, LOCK = EXCLUSIVE, ALGORITHM = NOCOPY  /* E_R Thread6 QNO 5739 CON_ID 263 */ ", packet_length=packet_length@entry=119, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/Server/bb-10.3-serg/sql/sql_parse.cc:1852

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