At last I have a simplified test case. I reduced one from innodb.instant_alter_crash and use a revision before fix for MDEV-18007 namely 330c6218dd1 to see a crash.
CREATE TABLE t2(id INT PRIMARY KEY, c2 INT UNIQUE) |
ENGINE=InnoDB;
|
INSERT INTO t2 VALUES(2,1); |
ALTER TABLE t2 ADD COLUMN (c3 TEXT NOT NULL DEFAULT 'De finibus bonorum'); |
|
|
INSERT INTO t2 VALUES (64,42,'De finibus bonorum'), (347,33101,' et malorum'); |
|
|
connect ddl, localhost, root; |
ALTER TABLE t2 DROP COLUMN c3; |
SET DEBUG_SYNC='innodb_alter_inplace_before_commit SIGNAL ddl WAIT_FOR ever'; |
--send
|
ALTER TABLE t2 ADD COLUMN (c4 TEXT NOT NULL DEFAULT ' et malorum'); |
|
|
connection default; |
SET DEBUG_SYNC='now WAIT_FOR ddl'; |
sleep 2;
|
|
|
--source include/kill_mysqld.inc
|
disconnect ddl;
|
--source include/start_mysqld.inc |
I run test with --gdb='b fsync;commands;bt;c;end;r' to see flushes to redo log and see this.
The last flush before sleep 2:
#0 fsync (fd=10) at fsync.c:27
|
#1 os_file_fsync_posix (file=10) at os0file.cc:2463
|
#2 os_file_flush_func (file=10) at os0file.cc:2564
|
#3 pfs_os_file_flush_func (file=..., src_file=0x17833f6 "/work/mariadb/storage/innobase/fil/fil0fil.cc", src_line=866) at os0file.ic:406
|
#4 fil_flush_low (space=0x2ba6e10) at fil0fil.cc:866
|
#5 fil_flush (space_id=4294967280) at fil0fil.cc:4559
|
#6 log_write_flush_to_disk_low () at log0log.cc:883
|
#7 log_write_up_to (lsn=157508, flush_to_disk=true, rotate_key=false) at log0log.cc:1121
|
#8 trx_flush_log_if_needed_low (lsn=157508) at trx0trx.cc:1192
|
#9 trx_flush_log_if_needed (lsn=157508, trx=0x7ffff05df318) at trx0trx.cc:1214
|
#10 trx_commit_in_memory (trx=0x7ffff05df318, mtr=0x7ffff02f0cd8) at trx0trx.cc:1419
|
#11 trx_commit_low (trx=0x7ffff05df318, mtr=0x7ffff02f0cd8) at trx0trx.cc:1547
|
#12 trx_commit (trx=0x7ffff05df318) at trx0trx.cc:1571
|
#13 trx_commit_for_mysql (trx=0x7ffff05df318) at trx0trx.cc:1707
|
#14 ha_innobase::commit_inplace_alter_table (this=0x7fffa0111870, altered_table=0x7fff9401bac8, ha_alter_info=0x7ffff02f4488, commit=true) at handler0alter.cc:10719
|
#15 handler::ha_commit_inplace_alter_table (this=0x7fffa0111870, altered_table=0x7fff9401bac8, ha_alter_info=0x7ffff02f4488, commit=true) at handler.cc:4492
|
#16 mysql_inplace_alter_table (thd=0x7fff94000cf8, table_list=0x7fff940130f8, table=0x7fffa0101508, altered_table=0x7fff9401bac8, ha_alter_info=0x7ffff02f4488, inplace_supported=HA_ALTER_INPLACE_INSTANT, target_mdl_request=0x7ffff02f4b28, alter_ctx=0x7ffff02f4cd8) at sql_table.cc:7590
|
#17 mysql_alter_table (thd=0x7fff94000cf8, new_db=0x7fff940053c0, new_name=0x7fff94005790, create_info=0x7ffff02f6020, table_list=0x7fff940130f8, alter_info=0x7ffff02f5f68, order_num=0, order=0x0, ignore=false) at sql_table.cc:9688
|
#18 Sql_cmd_alter_table::execute (this=0x7fff94013760, thd=0x7fff94000cf8) at sql_alter.cc:491
|
#19 mysql_execute_command (thd=0x7fff94000cf8) at sql_parse.cc:6301
|
#20 mysql_parse (thd=0x7fff94000cf8, rawbuf=0x7fff94013010 "ALTER TABLE t2 DROP COLUMN c3", length=29, parser_state=0x7ffff02f9500, is_com_multi=false, is_next_command=false) at sql_parse.cc:8103
|
LSN is 157508 here.
Then while sleep is in progress next flush happens:
#0 fsync (fd=10) at fsync.c:27
|
#1 os_file_fsync_posix (file=10) at os0file.cc:2463
|
#2 os_file_flush_func (file=10) at os0file.cc:2564
|
#3 pfs_os_file_flush_func (file=..., src_file=0x17833f6 "/work/mariadb/storage/innobase/fil/fil0fil.cc", src_line=866) at os0file.ic:406
|
#4 fil_flush_low (space=0x2ba6e10) at fil0fil.cc:866
|
#5 fil_flush (space_id=4294967280) at fil0fil.cc:4559
|
#6 log_write_flush_to_disk_low () at log0log.cc:883
|
#7 log_write_up_to (lsn=158121, flush_to_disk=true, rotate_key=false) at log0log.cc:1121
|
#8 log_buffer_sync_in_background (flush=true) at log0log.cc:1166
|
#9 srv_sync_log_buffer_in_background () at srv0srv.cc:1993
|
#10 srv_master_do_active_tasks () at srv0srv.cc:2160
|
#11 srv_master_thread (arg=0x0) at srv0srv.cc:2367
|
And LSN here is 158121 which is bigger than the previous 157508.
Async ALTER sleeps just before commit and thus before fsync() so there is nothing wrong that no flush happens before server kill without sleep for 2 seconds. I see nothing wrong in that test case.
After discussion with marko I've changed my test case to have a DML right before kill. It's purpose is to flush redo log, specifically, entries to not committed ALTER TABLE. It must call fsync() and it calls. All works as expected. I don't have a small test case now 
But in a instant_alter_crash I can see the real problem: fsync() is not called for DML. Here is how it should look like:
#0 fsync (fd=10) at fsync.c:27
|
#1 os_file_fsync_posix (file=10) at os0file.cc:2463
|
#2 os_file_flush_func (file=10) at os0file.cc:2564
|
#3 pfs_os_file_flush_func (file=..., src_file=0x17833f6 "/work/mariadb/storage/innobase/fil/fil0fil.cc", src_line=866) at os0file.ic:406
|
#4 fil_flush_low (space=0x2ba6e10) at fil0fil.cc:866
|
#5 fil_flush (space_id=4294967280) at fil0fil.cc:4559
|
#6 log_write_flush_to_disk_low () at log0log.cc:883
|
#7 log_write_up_to (lsn=163029, flush_to_disk=true, rotate_key=false) at log0log.cc:1121
|
#8 trx_flush_log_if_needed_low (lsn=163029) at trx0trx.cc:1192
|
#9 trx_flush_log_if_needed (lsn=163029, trx=0x7ffff05dd118) at trx0trx.cc:1214
|
#10 trx_commit_complete_for_mysql (trx=0x7ffff05dd118) at trx0trx.cc:1734
|
#11 innobase_commit (hton=0x2987a28, thd=0x7fffa0000cf8, commit_trx=false) at ha_innodb.cc:4641
|
#12 commit_one_phase_2 (thd=0x7fffa0000cf8, all=false, trans=0x7fffa0004228, is_real_trans=true) at handler.cc:1650
|
#13 ha_commit_one_phase (thd=0x7fffa0000cf8, all=false) at handler.cc:1630
|
#14 ha_commit_trans (thd=0x7fffa0000cf8, all=false) at handler.cc:1492
|
#15 trans_commit_stmt (thd=0x7fffa0000cf8) at transaction.cc:520
|
#16 mysql_execute_command (thd=0x7fffa0000cf8) at sql_parse.cc:6378
|
#17 mysql_parse (thd=0x7fffa0000cf8, rawbuf=0x7fffa00141a0 "delete from t1", length=14, parser_state=0x7ffff0344500, is_com_multi=false, is_next_command=false) at sql_parse.cc:8103
|
But in a instant_alter_crash() trx_flush_log_if_needed() is never called because trx->must_flush_log_later is somehow false here:
void
|
trx_commit_complete_for_mysql(
|
/*==========================*/
|
trx_t* trx) /*!< in/out: transaction */
|
{
|
if (trx->id != 0
|
|| !trx->must_flush_log_later
|
|| (srv_flush_log_at_trx_commit == 1 && trx->active_commit_ordered)) {
|
|
|
return;
|
}
|
|
|
trx_flush_log_if_needed(trx->commit_lsn, trx);
|
|
|
trx->must_flush_log_later = false;
|
}
|
At first glance condition looks suspicious: do not flush if do not must flush later which is flush now?
DELETE * FROM t1 has nothing to do because t1 is empty. That's why it doesn't write to redo log.
I backported the adjustment of the test to 10.3.15 and applied a minor follow-up fix.