MySQL Bugs: #68932: A regression in 5.6 crash recovery atomicity

Bug #68932	A regression in 5.6 crash recovery atomicity
Submitted:	11 Apr 2013 11:19	Modified:	6 Jun 2013 15:52
Reporter:	Laurynas Biveinis (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S1 (Critical)
Version:	5.6.10, 5.6.12	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	regression

Description:
A sequence of two crashes leaves the server with partially-written data in an InnoDB table. 

Please review the testcase below. The server performs insert into t1 select * from t2 in a transaction, where t2 has 10 rows, and then a crash is injected on commit. The crash recovery should result in either empty t1, either t1 having 10 rows. But after the second recovery t1 has only 9 rows. The same testcase run on 5.5 results in t1 with 10 rows.

The testcase is based on MariaDB's group_commit.test, which in turn claims to be based on Facebook patch.

On a related note, any progress on bug 60343? :)

How to repeat:
crash-master.opt:
--skip-stack-trace --skip-core-file

crash.test:

--source include/not_embedded.inc
--source include/not_valgrind.inc
--source include/have_debug.inc
--source include/have_innodb.inc
--source include/have_log_bin.inc

call mtr.add_suppression('Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT.');

CREATE TABLE t1(a CHAR(255),
                id INT AUTO_INCREMENT,
                PRIMARY KEY(id)) ENGINE=InnoDB;

create table t2 like t1;

# Avoid getting a crashed mysql.proc table.
FLUSH TABLES;

let $numinserts = 10;
while ($numinserts)
{
  dec $numinserts;
  INSERT INTO t2(a) VALUES ('a');
}
SELECT * FROM t2 ORDER BY id;

--enable_reconnect

RESET MASTER;

START TRANSACTION;
INSERT INTO t1(a) VALUES ('a');
--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect

SET SESSION debug="d,crash_commit_before";

--error 2006,2013
COMMIT;

--source include/wait_until_connected_again.inc

START TRANSACTION;
insert into t1 select * from t2;
--exec echo "restart" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect

SET SESSION debug="d,crash_commit_after";

--error 2006,2013
COMMIT;

--source include/wait_until_connected_again.inc

SELECT * FROM t1 ORDER BY id;

# final cleanup
DROP TABLE t1;
DROP TABLE t2;
# DROP PROCEDURE setcrash;

output (stock Oracle MySQL 5.6.10 from bzr, don't mind the path):

$ ./mysql-test-run crash --mem
Logging: /home/laurynas/percona/src/5.6/mysql-test/mysql-test-run.pl  crash --mem
2013-04-11 14:11:40 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151  table_cache: 431
2013-04-11 14:11:40 18974 [Note] Plugin 'FEDERATED' is disabled.
2013-04-11 14:11:40 18974 [Note] Binlog end
2013-04-11 14:11:40 18974 [Note] Shutting down plugin 'CSV'
2013-04-11 14:11:40 18974 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.10
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/laurynas/percona/src/5.6/obj/mysql-test/var'...
 - symlinking 'var' to '/dev/shm/var_auto_zRLR'
Installing system database...
Using server port 50632

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
call mtr.add_suppression('Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT.');
CREATE TABLE t1(a CHAR(255),
id INT AUTO_INCREMENT,
PRIMARY KEY(id)) ENGINE=InnoDB;
create table t2 like t1;
FLUSH TABLES;
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
INSERT INTO t2(a) VALUES ('a');
SELECT * FROM t2 ORDER BY id;
a	id
a	1
a	2
a	3
a	4
a	5
a	6
a	7
a	8
a	9
a	10
RESET MASTER;
START TRANSACTION;
INSERT INTO t1(a) VALUES ('a');
SET SESSION debug="d,crash_commit_before";
COMMIT;
Got one of the listed errors
START TRANSACTION;
insert into t1 select * from t2;
Warnings:
Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave.
SET SESSION debug="d,crash_commit_after";
COMMIT;
Got one of the listed errors
SELECT * FROM t1 ORDER BY id;
a	id
a	1
a	2
a	3
a	4
a	5
a	6
a	7
a	8
a	9
DROP TABLE t1;
DROP TABLE t2;
main.crash                               [ pass ]   4568
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 4.568 of 9 seconds executing testcases

Completed: All 1 tests were successful.

The same outcome happens if the second crash injection site is replaced with
crash_before_writing_xid
or
crash_commit_after_log
.

Removing RESET MASTER or replacing INSERT SELECT with regular INSERTs for the same data make the problem disappear.

Thank you for the report.

Verified as described. Option --mem makes failure more repeatable, but is not necessary to repeat the bug. Running ./mtr with option --repeat=100 can lead to similar failure as well.

Fixed in 5.6+. Documented in the 5.6.12 and 5.7.2 changelogs as follows:

        A crash-on-commit error followed by RESET MASTER caused InnoDB 
        to lose the previous transaction. This occurred because the
        prepare phase caused a flush to disk, while the commit phase did
        not perform a corresponding flush within InnoDB.

        To fix this problem, RESET MASTER now causes storage engine logs
        to be flushed on commit.

Closed.

For some mysterious reason the public bug # is not in the commit message.

5.6$ bzr log -r 5049
------------------------------------------------------------
revno: 5049
committer: Bill Qu <bill.qu@Oracle.com>
branch nick: mysql-5.6
timestamp: Sun 2013-04-28 09:21:43 +0800
message:
  Bug #16666456 	A REGRESSION IN 5.6 CRASH RECOVERY ATOMICITY
  
  A crash commit error causes the last transaction to loss in an InnoDB table after
  RESET MASTER. The root cause is that the prepare phase causes fsync while the
  commit phase does not cause fsync inside InnoDB. That means the last transaction
  is not fsynced inside InnoDB. But RESET MASTER erases binlog events of the last
  transaction. In the following crash commit error, InnoDB has the last prepared
  row on recovery and calls server on how to deal with the prepared row and server
  does not find relevant binlog events from binary log file and rolls it back finally.
  
  To fix the problem, RESET MASTER should cause to flush logs for storage engines, so
  that the last transaction is fsynced inside storage engines. The same solution to
  internal EXPIRE_LOGS_DAYS. There is not the problem with PURGE BINARY LOGS TO, as
  the binlog events of last transaction in current binlog file is not purged.