为何Binlog中同一个事务的event时间点会乱序？

woqutechteam

于 2019-01-16 10:12:28 发布

阅读量416

点赞数

分类专栏： MySQL 文章标签： MySQL Binlog 时间点乱序 GTID Query

本文链接：https://blog.csdn.net/woqutechteam/article/details/86502726

版权

本文详细探讨了MySQL Binlog中为何会出现同一个事务的event时间点乱序的现象。通过模拟用户更新操作，分析了在事务执行过程中不同event的生成时间，揭示了在事务提交时记录的GTID和commit语句event，以及在执行update语句时产生的其他event。文章适合对MySQL Binlog感兴趣的读者，特别是关注事务处理和日志顺序的数据库管理员。

摘要由CSDN通过智能技术生成

导语

这个问题，很久以前，笔者只是大概知道其中的原理，知道它就是长这样的，但并没有做过具体的案例分析。

直到某客户问起这个问题的时候，才发觉空口无凭讲不太清楚，遂现场给客户演示了一番才松了口气，也顺便把演示过程记录了下来，整理成文。下面请跟随我们一起来一探究竟吧！

服务器环境

1. 操作系统版本：CentOS release 6.5 (Final)

2. MySQL 版本：Oracle MySQL 5.7.20

3. MySQL 关键参数：innodb_flush_log_at_trx_commit=1; sync_binlog=1; binlog_format=row; gtid_mode=on; enforce_gtid_consistency=on

4. 验证所需数据：sysbench压测之后遗留的测试数据（可自行造数，只需要一张表中有一条数据即可）

验证准备

登录到数据库中，手动滚动一下binlog文件

root@localhost : sbtest 03:27:34> flush binary logs;select now();
Query OK, 0 rows affected (0.01 sec)
+---------------------+
| now() |
+---------------------+
| 2018-10-04 15:31:55 |  # 滚动binlog的时间点为2018-10-04 15:31:55
+---------------------+
1 row in set (0.00 sec)

解析一下最新的Binlog文件中的内容及其对应的时间点信息

[root@localhost binlog]# mysqlbinlog -vv mysql-bin.000460 
mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181004 15:31:55 server id 3306111 end_log_pos 123 CRC32 0x9cc61928 Start: binlog v 4, server v 5.7.20-log created 181004 15:31:55
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
68G1Ww9/cjIAdwAAAHsAAAABAAQANS43LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
ASgZxpw=
'/*!*/;
# at 123
#181004 15:31:55 server id 3306111 end_log_pos 194 CRC32 0xc34422d7 Previous-GTIDs
# ec123678-5e26-11e7-9d38-000c295e08a0:182318-199336
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

从上述binlog的解析内容来看，当前最新的binlog中，除了文件头的event之外，并没有其他用户数据产生的event数据，且文件头的所有event的时间点都为2018-10-04 15:31:55，这个时间点也是在数据库中手动执行binlog滚动语句的时间点，也就是说：binlog文件头的event是在binlog滚动时就已经产生且写入到了最新的binlog中，且这些event与用户数据无关。