[MDEV-18009] Missing redo log flush in innodb.instant_alter_crash - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.4(EOL)
Fix Version/s: 10.4.2, 10.3.15
Component/s: Storage Engine - InnoDB, Tests
Labels:
- recovery

Description

The test innodb.instant_alter_crash is supposed to flush the redo log before each time it kills the server. For some reason, it does not seem to be doing that. I was only able to repeat ~~MDEV-18007~~ by adding a sleep before each kill:

sleep 2;

--source include/kill_mysqld.inc

This bug could be affecting earlier versions as well.
I used to blame this on ~~MDEV-15740~~, but it could also be something else. I think that this can be pretty serious. Basically, losing committed transactions is breaking the Durability in ACID.

Attachments

Issue Links

relates to

MDEV-15740 Galera does not recover prepared XA-transactions correctly

Closed

MDEV-18007 innodb.instant_alter_crash : Assertion failed: n < tuple->n_fields, data0data.ic, line 433

Closed

Activity

Ascending order - Click to sort in descending order

Eugene Kosov (Inactive) added a comment - 2018-12-18 07:52 - edited

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

Eugene Kosov (Inactive) added a comment - 2018-12-18 07:52 - edited 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

Eugene Kosov (Inactive) added a comment - 2018-12-18 08:03

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.

Eugene Kosov (Inactive) added a comment - 2018-12-18 08:03 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.

Eugene Kosov (Inactive) added a comment - 2018-12-18 09:00

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.

Eugene Kosov (Inactive) added a comment - 2018-12-18 09:00 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.

Eugene Kosov (Inactive) added a comment - 2018-12-18 10:41

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?

Eugene Kosov (Inactive) added a comment - 2018-12-18 10:41 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?

Eugene Kosov (Inactive) added a comment - 2018-12-18 16:49

DELETE * FROM t1 has nothing to do because t1 is empty. That's why it doesn't write to redo log.

Eugene Kosov (Inactive) added a comment - 2018-12-18 16:49 DELETE * FROM t1 has nothing to do because t1 is empty. That's why it doesn't write to redo log.

Marko Mäkelä added a comment - 2019-05-09 09:42

I backported the adjustment of the test to 10.3.15 and applied a minor follow-up fix.

Marko Mäkelä added a comment - 2019-05-09 09:42 I backported the adjustment of the test to 10.3.15 and applied a minor follow-up fix .

People

Assignee:: Marko Mäkelä

Reporter:: Marko Mäkelä

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 2018-12-14 04:56

Updated:: 2019-05-09 09:42

Resolved:: 2018-12-20 16:23

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server