Jan Lindström (Inactive) added a comment - 2016-05-31 09:33 - edited innodb.group_commit_binlog_pos [ disabled ] MDEV-10156 innodb.group_commit_binlog_pos_no_optimize_thread [ disabled ] MDEV-10156

Jan Lindström (Inactive) added a comment - 2016-08-12 06:43 This with InnoDB 5.7 in branch bb-10.2-jan (please wait for email about status): --- /home/jan/mysql/10.2/mysql-test/suite/innodb/r/group_commit_binlog_pos_no_optimize_thread.result 2016-06-30 15:27:02.879686356 +0300 +++ /home/jan/mysql/10.2/mysql-test/suite/innodb/r/group_commit_binlog_pos_no_optimize_thread.reject 2016-08-12 09:40:33.801544117 +0300 @@ -44,6 +44,6 @@ 1 2 3 -InnoDB: Last MySQL binlog file position 0 <pos>, file name ./master-bin.000001 +InnoDB: Last MySQL binlog file position 0 645, file name ./master-bin.000001 SET DEBUG_SYNC= 'RESET'; DROP TABLE t1;   mysqltest: Result length mismatch   - saving '/dev/shm/log/innodb.group_commit_binlog_pos_no_optimize_thread-xtradb/' to '/dev/shm/log/innodb.group_commit_binlog_pos_no_optimize_thread-xtradb/' innodb.group_commit_crash_no_optimize_thread 'xtradb' [ pass ] 9963 innodb.group_commit_no_optimize_thread 'xtradb' [ pass ] 31 innodb.group_commit_binlog_pos 'xtradb' [ fail ] Test ended at 2016-08-12 09:40:50   CURRENT_TEST: innodb.group_commit_binlog_pos --- /home/jan/mysql/10.2/mysql-test/suite/innodb/r/group_commit_binlog_pos.result 2016-06-30 15:27:02.879686356 +0300 +++ /home/jan/mysql/10.2/mysql-test/suite/innodb/r/group_commit_binlog_pos.reject 2016-08-12 09:40:50.673675294 +0300 @@ -43,6 +43,6 @@ 1 2 3 -InnoDB: Last MySQL binlog file position 0 <pos>, file name ./master-bin.000001 +InnoDB: Last MySQL binlog file position 0 645, file name ./master-bin.000001 SET DEBUG_SYNC= 'RESET'; DROP TABLE t1;

Michael Widenius added a comment - 2016-08-29 17:55 In 10.2 base, the first 2 INSERT statements are committed and the last INSERT is in prepared stage when the server is forced to restart. In bb-10.2-jan all threads are in prepared stage when the server is restarted. This causes the binlog file position to be different, as this points to where in the binlog the last row was committed, which is now different. This can be see in this part of the mysqld.1.err log for the new tree: 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: Starting recovery for XA transactions... 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: Transaction 1286 in prepared state after recovery 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: Transaction contains changes to 1 rows 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: Transaction 1285 in prepared state after recovery 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: Transaction contains changes to 1 rows 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: Transaction 1284 in prepared state after recovery 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: Transaction contains changes to 1 rows 2016-08-29 12:12:07 140508343482240 [Note] InnoDB: 3 transactions in prepared state after recovery One possible reason for this is that the signalling of the condition con1_loop is now done before the transaction is fully committed.

Michael Widenius added a comment - 2016-08-30 13:50 Bug fix given to Jan Problem was that Innobase_commit didn't call trx_commit_complete_for_mysql()