Description:
When I wrote the test case for the Bug #24961167 CONCURRENT INSERT FAILS IF TABLE DOES REBUILD, I found a bug.
In the process of online DDL that need to rebuild the table, there are two replay of log record by calling row_log_table_apply_ops. But if the last insert log record is present across the blocks, mysqld would crash.
The log of mysqld shows:
InnoDB: Assertion failure in thread xxxxxxxxxxxx in file row0log.cc line 2997
InnoDB: Failing assertion: mrec < mrec_end
Because the log is last one, mrec should be equal to mrec_end.
After calling row_log_table_apply_op(row0log.cc:2936), the function should goto all_done if the log is last one, hence the judge should be necessary.
How to repeat:
file: alter_table_bug-master.opt
--innodb-sort-buffer-size=65536
file: alter_table_bug.test
--source include/have_innodb.inc
--source include/have_debug.inc
--source include/have_debug_sync.inc
# Bug :
# In the process of online DDL that need to rebuild the table,
# there are two replay of log record by calling row_log_table_apply_ops.
# If the last insert log record is present across the blocks, mysqld would crash.
# Example:
# Here innodb-sort-buffer-size is set to 65536.
# In the Table t1, the length of the insert log record is 6192 bytes.
# We can calculate that 65536/6192 = 10.58397932816537...
# Obviously, the 11th insert log record is present across the blocks.
# If the 11th insert log record is last one, mysqld would crash
# and 10th and 12th would be fine.
connect (con1,localhost,root,,);
connect (con2,localhost,root,,);
connection default;
show variables like '%innodb_sort_buffer_size%';
CREATE TABLE t1 (
col_1 char(255),
col_2 char(255),
col_3 char(255),
col_4 char(255),
col_5 char(255),
col_6 char(255),
col_7 char(255),
col_8 char(255),
col_9 char(255),
col_10 char(255),
col_11 char(255),
col_12 char(255),
col_13 char(255),
col_14 char(255),
col_15 char(255),
col_16 char(255),
col_17 char(255),
col_18 char(255),
col_19 char(255),
col_20 char(255),
col_21 char(255),
col_22 char(255),
col_23 char(255),
col_24 char(255)
)ENGINE=INNODB;
INSERT INTO t1(col_1,col_2,col_3,col_4,col_5,col_6,col_7,col_8,col_9,col_10,col_11,col_12,col_13,col_14,col_15,col_16,col_17,col_18,col_19,col_20,col_21,col_22,col_23,col_24) VALUES('a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a');
# Online DDL
connection con1;
SET DEBUG_SYNC= 'alter_table_inplace_after_lock_downgrade SIGNAL downgraded WAIT_FOR dml_done';
--send
ALTER TABLE t1 ADD COLUMN (col_25 int), ALGORITHM=INPLACE;
# Concurrent Insert
connection con2;
SET DEBUG_SYNC= 'now WAIT_FOR downgraded';
let $1=11;
--disable_query_log
while ($1)
{
eval INSERT INTO t1(col_1,col_2,col_3,col_4,col_5,col_6,col_7,col_8,col_9,col_10,col_11,col_12,col_13,col_14,col_15,col_16,col_17,col_18,col_19,col_20,col_21,col_22,col_23,col_24) VALUES('b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b');
dec $1;
}
--enable_query_log
SET DEBUG_SYNC= 'now SIGNAL dml_done';
disconnect con2;
connection con1;
reap;
disconnect con1;
## Cleanup
connection default;
SET DEBUG_SYNC='RESET';
DROP TABLE t1;
The stack:
=========
[Current thread is 1 (Thread 0x7f321a64d700 (LWP 60898))]
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
#1 0x0000556ad309bf75 in my_write_core (sig=6) at /home/ohmhong/codes/mysql-5.7/mysys/stacktrace.c:249
#2 0x0000556ad264aff2 in handle_fatal_signal (sig=6) at /home/ohmhong/codes/mysql-5.7/sql/signal_handler.cc:220
#3 <signal handler called>
#4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58
#5 0x00007f3224d0637a in __GI_abort () at abort.c:89
#6 0x0000556ad333f945 in ut_dbg_assertion_failed (expr=0x556ad3ac3983 "mrec < mrec_end", file=0x556ad3ac2af0 "/home/ohmhong/codes/mysql-5.7/storage/innobase/row/row0log.cc", line=2997) at /home/ohmhong/codes/mysql-5.7/storage/innobase/ut/ut0dbg.cc:67
#7 0x0000556ad3272a34 in row_log_table_apply_ops (thr=0x7f31bc04dac8, dup=0x7f321a649060, stage=0x7f31bc050718) at /home/ohmhong/codes/mysql-5.7/storage/innobase/row/row0log.cc:2997
#8 0x0000556ad32731b1 in row_log_table_apply (thr=0x7f31bc04dac8, old_table=0x7f31b80bc020, table=0x7f31bc01cf30, stage=0x7f31bc050718) at /home/ohmhong/codes/mysql-5.7/storage/innobase/row/row0log.cc:3136
#9 0x0000556ad313d46f in ha_innobase::inplace_alter_table (this=0x7f31bc00f300, altered_table=0x7f31bc01cf30, ha_alter_info=0x7f321a649390) at /home/ohmhong/codes/mysql-5.7/storage/innobase/handler/handler0alter.cc:6293
#10 0x0000556ad2ddeaa1 in handler::ha_inplace_alter_table (this=0x7f31bc00f300, altered_table=0x7f31bc01cf30, ha_alter_info=0x7f321a649390) at /home/ohmhong/codes/mysql-5.7/sql/handler.h:3398
#11 0x0000556ad2dd5d8b in mysql_inplace_alter_table (thd=0x7f31bc000b70, table_list=0x7f31bc0060f0, table=0x7f31bc00e950, altered_table=0x7f31bc01cf30, ha_alter_info=0x7f321a649390, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f321a6495b0, alter_ctx=0x7f321a649d00) at /home/ohmhong/codes/mysql-5.7/sql/sql_table.cc:7517
#12 0x0000556ad2ddb281 in mysql_alter_table (thd=0x7f31bc000b70, new_db=0x7f31bc006678 "test", new_name=0x0, create_info=0x7f321a64ad70, table_list=0x7f31bc0060f0, alter_info=0x7f321a64acc0) at /home/ohmhong/codes/mysql-5.7/sql/sql_table.cc:9705
#13 0x0000556ad2f62c35 in Sql_cmd_alter_table::execute (this=0x7f31bc006768, thd=0x7f31bc000b70) at /home/ohmhong/codes/mysql-5.7/sql/sql_alter.cc:329
#14 0x0000556ad2d3e106 in mysql_execute_command (thd=0x7f31bc000b70, first_level=true) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:4927
#15 0x0000556ad2d40485 in mysql_parse (thd=0x7f31bc000b70, parser_state=0x7f321a64c550) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:5722
#16 0x0000556ad2d34c2f in dispatch_command (thd=0x7f31bc000b70, com_data=0x7f321a64ce00, command=COM_QUERY) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:1461
#17 0x0000556ad2d33a78 in do_command (thd=0x7f31bc000b70) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:999
#18 0x0000556ad2e75b5e in handle_connection (arg=0x556ad623e1a0) at /home/ohmhong/codes/mysql-5.7/sql/conn_handler/connection_handler_per_thread.cc:308
#19 0x0000556ad3566a41 in pfs_spawn_thread (arg=0x556ad6258450) at /home/ohmhong/codes/mysql-5.7/storage/perfschema/pfs.cc:2188
#20 0x00007f32259456da in start_thread (arg=0x7f321a64d700) at pthread_create.c:456
#21 0x00007f3224dd717f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105
Suggested fix:
After calling row_log_table_apply_op(row0log.cc:2936), the function should goto all_done if the log is last one, hence the judge should be necessary.
Description: When I wrote the test case for the Bug #24961167 CONCURRENT INSERT FAILS IF TABLE DOES REBUILD, I found a bug. In the process of online DDL that need to rebuild the table, there are two replay of log record by calling row_log_table_apply_ops. But if the last insert log record is present across the blocks, mysqld would crash. The log of mysqld shows: InnoDB: Assertion failure in thread xxxxxxxxxxxx in file row0log.cc line 2997 InnoDB: Failing assertion: mrec < mrec_end Because the log is last one, mrec should be equal to mrec_end. After calling row_log_table_apply_op(row0log.cc:2936), the function should goto all_done if the log is last one, hence the judge should be necessary. How to repeat: file: alter_table_bug-master.opt --innodb-sort-buffer-size=65536 file: alter_table_bug.test --source include/have_innodb.inc --source include/have_debug.inc --source include/have_debug_sync.inc # Bug : # In the process of online DDL that need to rebuild the table, # there are two replay of log record by calling row_log_table_apply_ops. # If the last insert log record is present across the blocks, mysqld would crash. # Example: # Here innodb-sort-buffer-size is set to 65536. # In the Table t1, the length of the insert log record is 6192 bytes. # We can calculate that 65536/6192 = 10.58397932816537... # Obviously, the 11th insert log record is present across the blocks. # If the 11th insert log record is last one, mysqld would crash # and 10th and 12th would be fine. connect (con1,localhost,root,,); connect (con2,localhost,root,,); connection default; show variables like '%innodb_sort_buffer_size%'; CREATE TABLE t1 ( col_1 char(255), col_2 char(255), col_3 char(255), col_4 char(255), col_5 char(255), col_6 char(255), col_7 char(255), col_8 char(255), col_9 char(255), col_10 char(255), col_11 char(255), col_12 char(255), col_13 char(255), col_14 char(255), col_15 char(255), col_16 char(255), col_17 char(255), col_18 char(255), col_19 char(255), col_20 char(255), col_21 char(255), col_22 char(255), col_23 char(255), col_24 char(255) )ENGINE=INNODB; INSERT INTO t1(col_1,col_2,col_3,col_4,col_5,col_6,col_7,col_8,col_9,col_10,col_11,col_12,col_13,col_14,col_15,col_16,col_17,col_18,col_19,col_20,col_21,col_22,col_23,col_24) VALUES('a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a','a'); # Online DDL connection con1; SET DEBUG_SYNC= 'alter_table_inplace_after_lock_downgrade SIGNAL downgraded WAIT_FOR dml_done'; --send ALTER TABLE t1 ADD COLUMN (col_25 int), ALGORITHM=INPLACE; # Concurrent Insert connection con2; SET DEBUG_SYNC= 'now WAIT_FOR downgraded'; let $1=11; --disable_query_log while ($1) { eval INSERT INTO t1(col_1,col_2,col_3,col_4,col_5,col_6,col_7,col_8,col_9,col_10,col_11,col_12,col_13,col_14,col_15,col_16,col_17,col_18,col_19,col_20,col_21,col_22,col_23,col_24) VALUES('b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b','b'); dec $1; } --enable_query_log SET DEBUG_SYNC= 'now SIGNAL dml_done'; disconnect con2; connection con1; reap; disconnect con1; ## Cleanup connection default; SET DEBUG_SYNC='RESET'; DROP TABLE t1; The stack: ========= [Current thread is 1 (Thread 0x7f321a64d700 (LWP 60898))] #0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62 #1 0x0000556ad309bf75 in my_write_core (sig=6) at /home/ohmhong/codes/mysql-5.7/mysys/stacktrace.c:249 #2 0x0000556ad264aff2 in handle_fatal_signal (sig=6) at /home/ohmhong/codes/mysql-5.7/sql/signal_handler.cc:220 #3 <signal handler called> #4 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:58 #5 0x00007f3224d0637a in __GI_abort () at abort.c:89 #6 0x0000556ad333f945 in ut_dbg_assertion_failed (expr=0x556ad3ac3983 "mrec < mrec_end", file=0x556ad3ac2af0 "/home/ohmhong/codes/mysql-5.7/storage/innobase/row/row0log.cc", line=2997) at /home/ohmhong/codes/mysql-5.7/storage/innobase/ut/ut0dbg.cc:67 #7 0x0000556ad3272a34 in row_log_table_apply_ops (thr=0x7f31bc04dac8, dup=0x7f321a649060, stage=0x7f31bc050718) at /home/ohmhong/codes/mysql-5.7/storage/innobase/row/row0log.cc:2997 #8 0x0000556ad32731b1 in row_log_table_apply (thr=0x7f31bc04dac8, old_table=0x7f31b80bc020, table=0x7f31bc01cf30, stage=0x7f31bc050718) at /home/ohmhong/codes/mysql-5.7/storage/innobase/row/row0log.cc:3136 #9 0x0000556ad313d46f in ha_innobase::inplace_alter_table (this=0x7f31bc00f300, altered_table=0x7f31bc01cf30, ha_alter_info=0x7f321a649390) at /home/ohmhong/codes/mysql-5.7/storage/innobase/handler/handler0alter.cc:6293 #10 0x0000556ad2ddeaa1 in handler::ha_inplace_alter_table (this=0x7f31bc00f300, altered_table=0x7f31bc01cf30, ha_alter_info=0x7f321a649390) at /home/ohmhong/codes/mysql-5.7/sql/handler.h:3398 #11 0x0000556ad2dd5d8b in mysql_inplace_alter_table (thd=0x7f31bc000b70, table_list=0x7f31bc0060f0, table=0x7f31bc00e950, altered_table=0x7f31bc01cf30, ha_alter_info=0x7f321a649390, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7f321a6495b0, alter_ctx=0x7f321a649d00) at /home/ohmhong/codes/mysql-5.7/sql/sql_table.cc:7517 #12 0x0000556ad2ddb281 in mysql_alter_table (thd=0x7f31bc000b70, new_db=0x7f31bc006678 "test", new_name=0x0, create_info=0x7f321a64ad70, table_list=0x7f31bc0060f0, alter_info=0x7f321a64acc0) at /home/ohmhong/codes/mysql-5.7/sql/sql_table.cc:9705 #13 0x0000556ad2f62c35 in Sql_cmd_alter_table::execute (this=0x7f31bc006768, thd=0x7f31bc000b70) at /home/ohmhong/codes/mysql-5.7/sql/sql_alter.cc:329 #14 0x0000556ad2d3e106 in mysql_execute_command (thd=0x7f31bc000b70, first_level=true) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:4927 #15 0x0000556ad2d40485 in mysql_parse (thd=0x7f31bc000b70, parser_state=0x7f321a64c550) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:5722 #16 0x0000556ad2d34c2f in dispatch_command (thd=0x7f31bc000b70, com_data=0x7f321a64ce00, command=COM_QUERY) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:1461 #17 0x0000556ad2d33a78 in do_command (thd=0x7f31bc000b70) at /home/ohmhong/codes/mysql-5.7/sql/sql_parse.cc:999 #18 0x0000556ad2e75b5e in handle_connection (arg=0x556ad623e1a0) at /home/ohmhong/codes/mysql-5.7/sql/conn_handler/connection_handler_per_thread.cc:308 #19 0x0000556ad3566a41 in pfs_spawn_thread (arg=0x556ad6258450) at /home/ohmhong/codes/mysql-5.7/storage/perfschema/pfs.cc:2188 #20 0x00007f32259456da in start_thread (arg=0x7f321a64d700) at pthread_create.c:456 #21 0x00007f3224dd717f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105 Suggested fix: After calling row_log_table_apply_op(row0log.cc:2936), the function should goto all_done if the log is last one, hence the judge should be necessary.