这是一个朋友遇到的问题，他的现象大概如下（MySQL5.6）：

某个binlog实际大小8g左右，实际设置大小应该是1g

其中包含一个大事务，但是最后一个事务是小事务

查看大事务的XID_EVENT（‘commit’）时间和最后一个小事务XID_EVENT（‘commit’）时间差值近15分钟

下面是他提供的依据：

mysqlbinlog-vvmysqlbinlog_file>mysqlbinlog_res.loggrep-n-B1"COMMIT"mysqlbinlog_res.log>file.logtarzcffile.log.tar.gzfile.log通过结果可以看到大事务提交完成是binlog文件的行号是392578997，往前推一个事务，提交完成后的行号是42614752，期间相差3.2亿行，就是说这个事务总共写了3.2亿行的binlog大事务提交的时间是12:54:12，Xid=4103492840，结束的pos值是2915555141最后一个事务的提交时间13:08:43，Xid=4104544654，结束的pos值是2915740337

问：

为什么最后事务是小事务而不是最大的那个事务，为什么大事务束后没有切换binlog呢？

为什么最后一个小事务和大事务提交时间相差了15分钟之多呢？

一、提交流程图

这张图是基于MySQL5.7.22画的：

好了有了这张图我们继续分析。

二、为什么大事务会包含在一个binlog里面

如图中第10步我们可以看到在flush队列的事务Event都写到binlog（不是fsync）后才会进行binlog切换的标记，言外之意就是不管有多大的事务那么都要等到写完binlog后才进行切换标记的设置。因此大事务总是在一个binlog里面。

三、为什么最后事务是小事务而不是最大的那个事务

事实上在第10步中我们只是设置了切换标记而已，实际的切换会等到本事务所在的commit队列都提交完成后才会进行binlog的切换，具体就是参考第28步。

在这个期间会有2个原因导致大事务并不是binlog的最后一个事务：

对于flush队列而言，大事务可能包含在队列中的某个位置，队列后面可能包含小事务。

对于sync队列而言，大事务的提交会在sync阶段耗费很多时间，如果我们假设为30秒，那么在这30秒内其他新的事务是可以进入新的flush队列的，也能够进行写binlog（不是fsync）的操作。

因此线上有压力的库，binlog的最后一个事务通常不是大事务。

四、为什么最后一个小事务和大事务之间XID_EVENT（commit）时间相差了15分钟之多呢？

首先这个问题有两种可能：

对于自动事务提交，那么XID_EVENT会是命令发起的时间，因此更容易出现这种情况，后面会使用这种情况进行证明。

对于显示开启事务‘begin commit’，那么XID_EVENT会是commit命令发起的时间，但是如果fsync时间足够久那么也会出现这种问题。这种情况不容易测试，因为需要足够大的数据，人为测试很耗时。下面就是这种情况出现的原因。

关于以上两种情况的这种差别我已经在我的《深入理解MySQL主从原理 32讲》中第12讲、第14讲说明了原因。

这里我们就假定大事务的提交在sync阶段花费了大约15分钟，那么如下：





大事务flushT1

大事务sync开始T2小事务flushT2

小事务flushT3

小事务flushT4大事务sync结束T5



如果T5和T2之间相差15分钟左右，那么这期间进来的这些小事务依然保留在本binlog里面（因为还没切换29步才切换），那么就有可能看到小事务和大事务之间XID_EVENT（commit）时间相差很大了。

实际上在5.7中上面两种情况都很可能都会生成同样的last commit，因为这个时候由于大事务fsync的堵塞第22步更改last commit的操作是不能进行的。

五、在5.7.22中测试

整个测试过程必须卡准大事务进行提交这个时间点，我的参数设置如下：

max_binlog_size：1048576，设置较小的binlog大小方便测试。

binlog_group_commit_sync_delay：1000000，将本参数设置为1秒，用于拖长整个提交流程便于测试，但是实际上大事务的fsync操作可能会更加耗时。

binlog_transaction_dependency_tracking：COMMIT_ORDER，这是默认的配置，为了更好的证明我们前面生成同样的last commit的结论，避免writeset的干扰。

并且我在我的debug环境中设置了断点MYSQL_BIN_LOG::ordered_commit，用于更好的测试，否则自动提交事务的情况下非常难确认事务到底什么时候进行提交的。

最后我们不使用通过‘begin commit’显示的开启事务，因为这样XID_EVENT的时间是commit命令发起的时间，也就不太容易重现案例中的这种XID_EVENT大事务和小事务时间相差很大现象。但是实际上如果事务足够大也是可以的，因为在大事务如案例中有几亿的数据那么这个事务的sync过程会非常缓慢，但是我的测试环境没有那么多的数据，为了让测试效果更加明显因此使用自动提交，这样所有的Event都是命令发起的时间。

首先我做了一张较大的表有70W的数据，然后删除整个表的数据，显然这个事务的binlog会大于1M。下面这个表格就是操作流程：




T1：delete from testnnn;（70W行数据）

T2：进入提交流程断点触发


T3：delete from tm10;（1行数据）


T4：delete from tmpk;（1行数据）T5：所有事务提交完成



只要T4-T1的时间足够长那么就可能出现案例中的情况。如下是我的binlog的截图，可以看到binlog.000017为3.5M左右：

下面是我解析binlog.000017的最后部分内容，我们可以发现最后两个事务均是小事务，大事务并不是最后一个事务如下：

###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/###DELETEFROM`testmts`.`testnnn`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/#at3626617#19080422:56:10serverid413340end_log_pos3626648CRC320xfc5b79e7Xid=143COMMIT/*!*/;#at3626648#19080423:02:26serverid413340end_log_pos3626713CRC320xa2399157GTIDlast_committed=0sequence_number=2rbr_only=yes/*!50718SETTRANSACTIONISOLATIONLEVELREADCOMMITTED*//*!*/;SET@@SESSION.GTID_NEXT='cb7ea36e-670f-11e9-b483-5254008138e4:191'/*!*/;#at3626713#19080423:02:26serverid413340end_log_pos3626788CRC320x555fb49dQuerythread_id=4exec_time=0error_code=0SETTIMESTAMP=1564930946/*!*/;BEGIN/*!*/;#at3626788#19080423:02:26serverid413340end_log_pos3626838CRC320xec0a4316Table_map:`testmts`.`tm10`mappedtonumber149#at3626838#19080423:02:26serverid413340end_log_pos3626878CRC320x61c79d68Delete_rows:tableid149flags:STMT_END_F###DELETEFROM`testmts`.`tm10`###WHERE###@1=10/*INTmeta=0nullable=1is_null=0*/#at3626878#19080423:02:26serverid413340end_log_pos3626909CRC320x2a9cd136Xid=154COMMIT/*!*/;#at3626909#19080423:02:26serverid413340end_log_pos3626974CRC320x06b081ecGTIDlast_committed=0sequence_number=3rbr_only=yes/*!50718SETTRANSACTIONISOLATIONLEVELREADCOMMITTED*//*!*/;SET@@SESSION.GTID_NEXT='cb7ea36e-670f-11e9-b483-5254008138e4:192'/*!*/;#at3626974#19080423:02:26serverid413340end_log_pos3627049CRC320x0e214995Querythread_id=5exec_time=1error_code=0SETTIMESTAMP=1564930946/*!*/;BEGIN/*!*/;#at3627049#19080423:02:26serverid413340end_log_pos3627104CRC320x8ee0af93Table_map:`testmts`.`tmpk`mappedtonumber150#at3627104#19080423:02:26serverid413340end_log_pos3627154CRC320x4804be49Delete_rows:tableid150flags:STMT_END_F###DELETEFROM`testmts`.`tmpk`###WHERE###@1=1/*INTmeta=0nullable=0is_null=0*/###@2='g'/*VARSTRING(60)meta=60nullable=1is_null=0*/###@3=1/*INTmeta=0nullable=1is_null=0*/###@4=1/*INTmeta=0nullable=1is_null=0*/#at3627154#19080423:02:26serverid413340end_log_pos3627185CRC320x64f2ea15Xid=153COMMIT/*!*/;

仔细观察你会发现 23:02:26和22:56:10之间相差了6分钟之多。然后我们来看看他们的last commit如下：

[root@mysqltest2log]#cat-nlog.log|greplast11#19080422:56:10serverid413340end_log_pos299CRC320x47602f13GTIDlast_committed=0sequence_number=1rbr_only=yes2167349#19080423:02:26serverid413340end_log_pos3626713CRC320xa2399157GTIDlast_committed=0sequence_number=2rbr_only=yes2167368#19080423:02:26serverid413340end_log_pos3626974CRC320x06b081ecGTIDlast_committed=0sequence_number=3rbr_only=yes

我们发现如我们所述，它们的last commit是一致的。到这里我们全部的结论都得到证明。