Bug #87532 Replay log record cause mysqld crash during online DDL
Submitted: 24 Aug 2017 15:56 Modified: 9 Feb 20:26
Reporter: ohm hong Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.7.19 OS:Any
Assigned to: CPU Architecture:Any

[24 Aug 2017 15:56] ohm hong
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.
[25 Aug 2017 15:05] Bogdan Kecman
Hi,

Thanks for the test case. Verified.

all best
Bogdan
[9 Feb 20:26] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 5.6.40, 5.7.22, 8.0.5 release, and here's the changelog entry:

An online DDL operation that rebuilds the table raised an assertion when the 
last insert log record to be applied was split across two pages.