Description:
Some online DDL operations scenes, which need rebuilding the table, may access out-of-bounds memory. crash stack like:
#6 0x00000000057607a4 in ut_dbg_assertion_failed (expr=0x804c564 "ptr == end_ptr", file=0x804bb18 "/home/lb/hwsql/80/storage/innobase/trx/trx0rec.cc", line=2754) at /home/lb/hwsql/80/storage/innobase/ut/ut0dbg.cc:99
#7 0x000000000570fc13 in trx_undo_read_v_cols (table=0x7f6ce8f8e0c0, ptr=0x7f6d1d23a46e "", row=0x7f6ce8f9bf40, in_purge=false, online=true, col_map=0x7f6ce8ef8d10, heap=0x7f6ce8f9bea0) at /home/lb/hwsql/80/storage/innobase/trx/trx0rec.cc:2754
#8 0x00000000055c4821 in row_log_table_apply_op (thr=0x7f6ce8e07ab8, trx_id_col=1, new_trx_id_col=1, dup=0x7f6d125e19f0, error=0x7f6d125e1634, offsets_heap=0x7f6ce8e769a0, heap=0x7f6ce8f9bea0, mrec=0x7f6d1d23a060 "", mrec_end=0x7f6d1d23a468 "", offsets=0x7f6ce8e2e870) at /home/lb/hwsql/80/storage/innobase/row/row0log.cc:2573
#9 0x00000000055c5be9 in row_log_table_apply_ops (thr=0x7f6ce8e07ab8, dup=0x7f6d125e19f0, stage=0x7f6ce8e2e800) at /home/lb/hwsql/80/storage/innobase/row/row0log.cc:2925
#10 0x00000000055c6091 in row_log_table_apply (thr=0x7f6ce8e07ab8, old_table=0x7f6cea2ee0c0, table=0x7f6ce8f06030, stage=0x7f6ce8e2e800) at /home/lb/hwsql/80/storage/innobase/row/row0log.cc:3015
#11 0x000000000535cd97 in ha_innobase::inplace_alter_table_impl<dd::Table> (this=0x7f6ce8eae038, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, old_dd_tab=0x7f6ce9b4c210, new_dd_tab=0x7f6ce9b4d010) at /home/lb/hwsql/80/storage/innobase/handler/handler0alter.cc:6144
#12 0x0000000005337987 in ha_innobase::inplace_alter_table (this=0x7f6ce8eae038, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, old_dd_tab=0x7f6ce9b4c210, new_dd_tab=0x7f6ce9b4d010) at /home/lb/hwsql/80/storage/innobase/handler/handler0alter.cc:1282
#13 0x0000000003446702 in handler::ha_inplace_alter_table (this=0x7f6ce8eae038, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, old_table_def=0x7f6ce9b4c210, new_table_def=0x7f6ce9b4d010) at /home/lb/hwsql/80/sql/handler.h:5908
#14 0x0000000003429e19 in mysql_inplace_alter_table (thd=0x7f6ce8e0b000, schema=..., new_schema=..., table_def=0x7f6ce9b4c210, altered_table_def=0x7f6ce9b4d010, table_list=0x7f6ce8e5ddd8, table=0x7f6cea1ee430, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, alter_ctx=0x7f6d125e33d0, columns=std::set with 0 elements, fk_key_info=0x7f6ce8e106b8, fk_key_count=0, fk_invalidator=0x7f6d125e3300) at /home/lb/hwsql/80/sql/sql_table.cc:13035
#15 0x00000000034358cf in mysql_alter_table (thd=0x7f6ce8e0b000, new_db=0x0, new_name=0x0, create_info=0x7f6d125e48f0, table_list=0x7f6ce8e5ddd8, alter_info=0x7f6d125e4780) at /home/lb/hwsql/80/sql/sql_table.cc:17044
#16 0x0000000003439da6 in mysql_recreate_table (thd=0x7f6ce8e0b000, table_list=0x7f6ce8e5ddd8, table_copy=false) at /home/lb/hwsql/80/sql/sql_table.cc:18292
#17 0x0000000003c9dd18 in mysql_admin_table (thd=0x7f6ce8e0b000, tables=0x7f6ce8e5ddd8, check_opt=0x7f6ce8e353b0, operator_name=0x73e61a6 "optimize", lock_type=TL_WRITE, open_for_modify=false, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x3897c12 <handler::ha_optimize(THD*, HA_CHECK_OPT*)>, check_view=0, alter_info=0x7f6ce8e5dc58, need_to_acquire_shared_backup_lock=true) at /home/lb/hwsql/80/sql/sql_admin.cc:1129
#18 0x0000000003c9f83b in Sql_cmd_optimize_table::execute (this=0x7f6ce8e5e400, thd=0x7f6ce8e0b000) at /home/lb/hwsql/80/sql/sql_admin.cc:1610
#19 0x000000000330dc65 in mysql_execute_command (thd=0x7f6ce8e0b000, first_level=true) at /home/lb/hwsql/80/sql/sql_parse.cc:4672
#20 0x000000000330fc7d in dispatch_sql_command (thd=0x7f6ce8e0b000, parser_state=0x7f6d125e6990) at /home/lb/hwsql/80/sql/sql_parse.cc:5269
#21 0x00000000033056f9 in dispatch_command (thd=0x7f6ce8e0b000, com_data=0x7f6d125e73f0, command=COM_QUERY) at /home/lb/hwsql/80/sql/sql_parse.cc:1903
#22 0x0000000003303a35 in do_command (thd=0x7f6ce8e0b000) at /home/lb/hwsql/80/sql/sql_parse.cc:1335
#23 0x0000000003613417 in handle_connection (arg=0x7f6d15bcf120) at /home/lb/hwsql/80/sql/conn_handler/connection_handler_per_thread.cc:309
#24 0x0000000005ec0572 in pfs_spawn_thread (arg=0x7f6d1ce28770) at /home/lb/hwsql/80/storage/perfschema/pfs.cc:2899
#25 0x00007f6d1f10dea5 in start_thread () from /lib64/libpthread.so.0
#26 0x00007f6d1d6cbb0d in clone () from /lib64/libc.so.6
or
08:19:12 UTC - mysqld got signal 11 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x7fbe55505000
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7fbe7e21b4f8 thread_stack 0x46000
2021-11-10T16:19:12.977948+08:00 927 140456519055104 [Note] [MY-011825] [InnoDB] fil_space_create, name: test/#sql-ib16628520-3703212968, space_id:16629850 at file: /data/fuxi_ci_workspace/6181ea9e2533b0002d0cb02a/src/sql/storage/innobase/fil/fil0fil.cc, line: 5964, succeed!
/opt/taurus/sql/bin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x2e) [0x242e68e]
/opt/taurus/sql/bin/mysqld(handle_fatal_signal+0x303) [0x1277bc3]
/lib64/libpthread.so.0(+0xf5c0) [0x7fc1138045c0]
/opt/taurus/sql/bin/mysqld(trx_undo_read_v_cols(dict_table_t const*, unsigned char const*, dtuple_t const*, bool, bool, unsigned long const*, mem_block_info_t*)+0x14b) [0x27fcccb]
/opt/taurus/sql/bin/mysqld() [0x2751719]
/opt/taurus/sql/bin/mysqld() [0x2753cf5]
/opt/taurus/sql/bin/mysqld(row_log_table_apply(que_thr_t*, dict_table_t*, TABLE*, ut_stage_alter_t*)+0x178) [0x2754cf8]
/opt/taurus/sql/bin/mysqld(bool ha_innobase::inplace_alter_table_impl(TABLE*, Alter_inplace_info*, dd::Partition const*, dd::Partition*)+0x6b4) [0x2604674]
/opt/taurus/sql/bin/mysqld(ha_innopart::inplace_alter_table(TABLE*, Alter_inplace_info*, dd::Table const*, dd::Table*)+0x16f) [0x261853f]
/opt/taurus/sql/bin/mysqld() [0x11abbe9]
/opt/taurus/sql/bin/mysqld(mysql_alter_table(THD*, char const*, char const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*)+0x4d86) [0x11c6aa6]
/opt/taurus/sql/bin/mysqld(mysql_recreate_table(THD*, TABLE_LIST*, bool)+0x33e) [0x11cbbae]
/opt/taurus/sql/bin/mysqld() [0x164a9c9]
/opt/taurus/sql/bin/mysqld(Sql_cmd_optimize_table::execute(THD*)+0xa9) [0x164b4c9]
/opt/taurus/sql/bin/mysqld(Sql_cmd_optimize_table::execute(THD*)+0xa9) [0x164b4c9]
/opt/taurus/sql/bin/mysqld(mysql_execute_command(THD*, bool)+0xcb1) [0x1104911]
/opt/taurus/sql/bin/mysqld(mysql_parse(THD*, Parser_state*, bool)+0x4b9) [0x1109e79]
/opt/taurus/sql/bin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x1d75) [0x110c0e5]
/opt/taurus/sql/bin/mysqld(do_command(THD*)+0x246) [0x110cf46]
/opt/taurus/sql1130/lib/plugin/threadpool.so(threadpool_process_request(THD*)+0xb9) [0x7fbf605bab29]
/opt/taurus/sql1130/lib/plugin/threadpool.so(+0x4b25) [0x7fbf605bbb25]
/opt/taurus/sql/bin/mysqld() [0x2a9fd16]
/lib64/libpthread.so.0(+0x7e45) [0x7fc1137fce45]
/lib64/libc.so.6(clone+0x6d) [0x7fc110066b3d]
How to repeat:
Run the following mtr testcase
cat mysql-test/suite/innodb/t/innodb_online_log_out_bounds_access-master.opt
--innodb_sort_buffer_size=66664
cat mysql-test/suite/innodb/t/innodb_online_log_out_bounds_access.test
--source include/have_debug.inc
--source include/have_debug_sync.inc
--source include/count_sessions.inc
show global variables like "innodb_sort_buffer_size";
connect(conn1,localhost,root,,);
connect(conn2,localhost,root,,);
connection default;
--disable_query_log
CREATE TABLE t1(
id INT,
name VARCHAR(1000),
g_col VARCHAR(20) GENERATED ALWAYS AS (concat(id, substr(`name`, 0, 10))) VIRTUAL,
KEY idx_id_g_col(id, g_col));
let $i= 0;
while ($i < 80)
{
eval INSERT INTO `t1`(id, name) VALUES($i, repeat("a",1000));
inc $i;
}
--enable_query_log
# main operation
connection conn1;
SET debug_sync = 'alter_table_update_log signal send_concurrent WAIT_FOR concurrent_done';
--send OPTIMIZE TABLE t1;
# concurrent operations
connection conn2;
SET debug_sync = 'now wait_for send_concurrent';
UPDATE t1 SET id = id + 1;
SET debug_sync = 'now signal concurrent_done';
disconnect conn2;
connection conn1;
reap;
disconnect conn1;
# teardown
connection default;
DROP TABLE t1;
--source include/wait_until_count_sessions.inc
Suggested fix:
Check whether or not mysqld will access out-of-bounds memory when construct an old pk row with virtual col value during applying an updated online log.
Description: Some online DDL operations scenes, which need rebuilding the table, may access out-of-bounds memory. crash stack like: #6 0x00000000057607a4 in ut_dbg_assertion_failed (expr=0x804c564 "ptr == end_ptr", file=0x804bb18 "/home/lb/hwsql/80/storage/innobase/trx/trx0rec.cc", line=2754) at /home/lb/hwsql/80/storage/innobase/ut/ut0dbg.cc:99 #7 0x000000000570fc13 in trx_undo_read_v_cols (table=0x7f6ce8f8e0c0, ptr=0x7f6d1d23a46e "", row=0x7f6ce8f9bf40, in_purge=false, online=true, col_map=0x7f6ce8ef8d10, heap=0x7f6ce8f9bea0) at /home/lb/hwsql/80/storage/innobase/trx/trx0rec.cc:2754 #8 0x00000000055c4821 in row_log_table_apply_op (thr=0x7f6ce8e07ab8, trx_id_col=1, new_trx_id_col=1, dup=0x7f6d125e19f0, error=0x7f6d125e1634, offsets_heap=0x7f6ce8e769a0, heap=0x7f6ce8f9bea0, mrec=0x7f6d1d23a060 "", mrec_end=0x7f6d1d23a468 "", offsets=0x7f6ce8e2e870) at /home/lb/hwsql/80/storage/innobase/row/row0log.cc:2573 #9 0x00000000055c5be9 in row_log_table_apply_ops (thr=0x7f6ce8e07ab8, dup=0x7f6d125e19f0, stage=0x7f6ce8e2e800) at /home/lb/hwsql/80/storage/innobase/row/row0log.cc:2925 #10 0x00000000055c6091 in row_log_table_apply (thr=0x7f6ce8e07ab8, old_table=0x7f6cea2ee0c0, table=0x7f6ce8f06030, stage=0x7f6ce8e2e800) at /home/lb/hwsql/80/storage/innobase/row/row0log.cc:3015 #11 0x000000000535cd97 in ha_innobase::inplace_alter_table_impl<dd::Table> (this=0x7f6ce8eae038, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, old_dd_tab=0x7f6ce9b4c210, new_dd_tab=0x7f6ce9b4d010) at /home/lb/hwsql/80/storage/innobase/handler/handler0alter.cc:6144 #12 0x0000000005337987 in ha_innobase::inplace_alter_table (this=0x7f6ce8eae038, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, old_dd_tab=0x7f6ce9b4c210, new_dd_tab=0x7f6ce9b4d010) at /home/lb/hwsql/80/storage/innobase/handler/handler0alter.cc:1282 #13 0x0000000003446702 in handler::ha_inplace_alter_table (this=0x7f6ce8eae038, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, old_table_def=0x7f6ce9b4c210, new_table_def=0x7f6ce9b4d010) at /home/lb/hwsql/80/sql/handler.h:5908 #14 0x0000000003429e19 in mysql_inplace_alter_table (thd=0x7f6ce8e0b000, schema=..., new_schema=..., table_def=0x7f6ce9b4c210, altered_table_def=0x7f6ce9b4d010, table_list=0x7f6ce8e5ddd8, table=0x7f6cea1ee430, altered_table=0x7f6ce8f06030, ha_alter_info=0x7f6d125e24d0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, alter_ctx=0x7f6d125e33d0, columns=std::set with 0 elements, fk_key_info=0x7f6ce8e106b8, fk_key_count=0, fk_invalidator=0x7f6d125e3300) at /home/lb/hwsql/80/sql/sql_table.cc:13035 #15 0x00000000034358cf in mysql_alter_table (thd=0x7f6ce8e0b000, new_db=0x0, new_name=0x0, create_info=0x7f6d125e48f0, table_list=0x7f6ce8e5ddd8, alter_info=0x7f6d125e4780) at /home/lb/hwsql/80/sql/sql_table.cc:17044 #16 0x0000000003439da6 in mysql_recreate_table (thd=0x7f6ce8e0b000, table_list=0x7f6ce8e5ddd8, table_copy=false) at /home/lb/hwsql/80/sql/sql_table.cc:18292 #17 0x0000000003c9dd18 in mysql_admin_table (thd=0x7f6ce8e0b000, tables=0x7f6ce8e5ddd8, check_opt=0x7f6ce8e353b0, operator_name=0x73e61a6 "optimize", lock_type=TL_WRITE, open_for_modify=false, repair_table_use_frm=false, extra_open_options=0, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x3897c12 <handler::ha_optimize(THD*, HA_CHECK_OPT*)>, check_view=0, alter_info=0x7f6ce8e5dc58, need_to_acquire_shared_backup_lock=true) at /home/lb/hwsql/80/sql/sql_admin.cc:1129 #18 0x0000000003c9f83b in Sql_cmd_optimize_table::execute (this=0x7f6ce8e5e400, thd=0x7f6ce8e0b000) at /home/lb/hwsql/80/sql/sql_admin.cc:1610 #19 0x000000000330dc65 in mysql_execute_command (thd=0x7f6ce8e0b000, first_level=true) at /home/lb/hwsql/80/sql/sql_parse.cc:4672 #20 0x000000000330fc7d in dispatch_sql_command (thd=0x7f6ce8e0b000, parser_state=0x7f6d125e6990) at /home/lb/hwsql/80/sql/sql_parse.cc:5269 #21 0x00000000033056f9 in dispatch_command (thd=0x7f6ce8e0b000, com_data=0x7f6d125e73f0, command=COM_QUERY) at /home/lb/hwsql/80/sql/sql_parse.cc:1903 #22 0x0000000003303a35 in do_command (thd=0x7f6ce8e0b000) at /home/lb/hwsql/80/sql/sql_parse.cc:1335 #23 0x0000000003613417 in handle_connection (arg=0x7f6d15bcf120) at /home/lb/hwsql/80/sql/conn_handler/connection_handler_per_thread.cc:309 #24 0x0000000005ec0572 in pfs_spawn_thread (arg=0x7f6d1ce28770) at /home/lb/hwsql/80/storage/perfschema/pfs.cc:2899 #25 0x00007f6d1f10dea5 in start_thread () from /lib64/libpthread.so.0 #26 0x00007f6d1d6cbb0d in clone () from /lib64/libc.so.6 or 08:19:12 UTC - mysqld got signal 11 ; Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware. Thread pointer: 0x7fbe55505000 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 7fbe7e21b4f8 thread_stack 0x46000 2021-11-10T16:19:12.977948+08:00 927 140456519055104 [Note] [MY-011825] [InnoDB] fil_space_create, name: test/#sql-ib16628520-3703212968, space_id:16629850 at file: /data/fuxi_ci_workspace/6181ea9e2533b0002d0cb02a/src/sql/storage/innobase/fil/fil0fil.cc, line: 5964, succeed! /opt/taurus/sql/bin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x2e) [0x242e68e] /opt/taurus/sql/bin/mysqld(handle_fatal_signal+0x303) [0x1277bc3] /lib64/libpthread.so.0(+0xf5c0) [0x7fc1138045c0] /opt/taurus/sql/bin/mysqld(trx_undo_read_v_cols(dict_table_t const*, unsigned char const*, dtuple_t const*, bool, bool, unsigned long const*, mem_block_info_t*)+0x14b) [0x27fcccb] /opt/taurus/sql/bin/mysqld() [0x2751719] /opt/taurus/sql/bin/mysqld() [0x2753cf5] /opt/taurus/sql/bin/mysqld(row_log_table_apply(que_thr_t*, dict_table_t*, TABLE*, ut_stage_alter_t*)+0x178) [0x2754cf8] /opt/taurus/sql/bin/mysqld(bool ha_innobase::inplace_alter_table_impl(TABLE*, Alter_inplace_info*, dd::Partition const*, dd::Partition*)+0x6b4) [0x2604674] /opt/taurus/sql/bin/mysqld(ha_innopart::inplace_alter_table(TABLE*, Alter_inplace_info*, dd::Table const*, dd::Table*)+0x16f) [0x261853f] /opt/taurus/sql/bin/mysqld() [0x11abbe9] /opt/taurus/sql/bin/mysqld(mysql_alter_table(THD*, char const*, char const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*)+0x4d86) [0x11c6aa6] /opt/taurus/sql/bin/mysqld(mysql_recreate_table(THD*, TABLE_LIST*, bool)+0x33e) [0x11cbbae] /opt/taurus/sql/bin/mysqld() [0x164a9c9] /opt/taurus/sql/bin/mysqld(Sql_cmd_optimize_table::execute(THD*)+0xa9) [0x164b4c9] /opt/taurus/sql/bin/mysqld(Sql_cmd_optimize_table::execute(THD*)+0xa9) [0x164b4c9] /opt/taurus/sql/bin/mysqld(mysql_execute_command(THD*, bool)+0xcb1) [0x1104911] /opt/taurus/sql/bin/mysqld(mysql_parse(THD*, Parser_state*, bool)+0x4b9) [0x1109e79] /opt/taurus/sql/bin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x1d75) [0x110c0e5] /opt/taurus/sql/bin/mysqld(do_command(THD*)+0x246) [0x110cf46] /opt/taurus/sql1130/lib/plugin/threadpool.so(threadpool_process_request(THD*)+0xb9) [0x7fbf605bab29] /opt/taurus/sql1130/lib/plugin/threadpool.so(+0x4b25) [0x7fbf605bbb25] /opt/taurus/sql/bin/mysqld() [0x2a9fd16] /lib64/libpthread.so.0(+0x7e45) [0x7fc1137fce45] /lib64/libc.so.6(clone+0x6d) [0x7fc110066b3d] How to repeat: Run the following mtr testcase cat mysql-test/suite/innodb/t/innodb_online_log_out_bounds_access-master.opt --innodb_sort_buffer_size=66664 cat mysql-test/suite/innodb/t/innodb_online_log_out_bounds_access.test --source include/have_debug.inc --source include/have_debug_sync.inc --source include/count_sessions.inc show global variables like "innodb_sort_buffer_size"; connect(conn1,localhost,root,,); connect(conn2,localhost,root,,); connection default; --disable_query_log CREATE TABLE t1( id INT, name VARCHAR(1000), g_col VARCHAR(20) GENERATED ALWAYS AS (concat(id, substr(`name`, 0, 10))) VIRTUAL, KEY idx_id_g_col(id, g_col)); let $i= 0; while ($i < 80) { eval INSERT INTO `t1`(id, name) VALUES($i, repeat("a",1000)); inc $i; } --enable_query_log # main operation connection conn1; SET debug_sync = 'alter_table_update_log signal send_concurrent WAIT_FOR concurrent_done'; --send OPTIMIZE TABLE t1; # concurrent operations connection conn2; SET debug_sync = 'now wait_for send_concurrent'; UPDATE t1 SET id = id + 1; SET debug_sync = 'now signal concurrent_done'; disconnect conn2; connection conn1; reap; disconnect conn1; # teardown connection default; DROP TABLE t1; --source include/wait_until_count_sessions.inc Suggested fix: Check whether or not mysqld will access out-of-bounds memory when construct an old pk row with virtual col value during applying an updated online log.