AI 助理
备案控制台
开发者社区 数据库 文章 正文

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

2018-12-11 2916
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
本文涉及的产品
云数据库 RDS MySQL，集群系列 2核4GB
推荐场景：
搭建个人博客
RDS MySQL Serverless 基础系列，0.5-2RCU 50GB
推荐场景：
学生管理系统数据库设计 搭建个人博客
云数据库 RDS PostgreSQL，集群系列 2核4GB
简介：

导 读

作者：罗小波·沃趣科技高级数据库技术专家

IT从业多年，历任运维工程师、高级运维工程师、运维经理、数据库工程师，曾参与版本发布系统、轻量级监控系统、运维管理平台、数据库管理平台的设计与编写，熟悉MySQL体系结构，Innodb存储引擎，喜好专研开源技术，追求完美。

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

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

一、服务器环境

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与用户数据无关。

三、验证过程
接下来我们模拟用户对数据执行update操作，且为了验证需要，我们使用了显式事务，且在事务执行过程中人为加入了停顿，以便更清晰地看到binlog中的event是如何记录的。

首先，登录到数据库中，显式开启一个事务。

# 查询测试数据，以便后续编写update语句

root@localhost : sbtest 03:31:55> select * from sbtest1 limit 1;

+----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+

| id | k | c | pad |

+----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+

| 21 | 2483477 | 09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849 | xxx |

+----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+

1 row in set (0.00 sec)

# 显式开启一个事务

root@localhost : sbtest 03:32:17> begin;select now();

Query OK, 0 rows affected (0.00 sec)

+---------------------+

| now() |

+---------------------+

| 2018-10-04 15:33:02|  # begin语句时间点为 2018-10-04 15:33:02

+---------------------+

1 row in set (0.00 sec)

这个时候，binlog中还未记录新事务的binlog日志，等待几十秒之后，再在数据库中执行update语句修改k列值（这里是单行修改，且sbtest1表的id列为主键，所以update语句执行时间在这里是极小的，可以忽略不计）

root@localhost : sbtest 03:33:02> update sbtest1 set k=k+1 where id=21;select now();

Query OK, 1 row affected (0.00 sec)

Rows matched: 1 Changed: 1 Warnings: 0

+---------------------+

| now() |

+---------------------+

| 2018-10-04 15:35:21 |  # update语句执行的时间点为 2018-10-04 15:35:21

+---------------------+

1 row in set (0.00 sec)

这个时候，binlog中仍然还未记录新事务的binlog日志（因为事务并没有提交，binlog只会在事务提交时才会写入binlog文件中），现在，我们对该显式事务执行commit语句提交事务。

root@localhost : sbtest 03:35:21> commit;select now();

Query OK, 0 rows affected (0.01 sec)

+---------------------+

| now() |

+---------------------+

| 2018-10-04 15:36:42 | # commit语句执行的时间点为 2018-10-04 15:36:42

+---------------------+

1 row in set (0.00 sec)

现在，我们解析最新的binlog文件，查看此时binlog中是如何记录该事务产生的event数据的（注意：binlog 中每个event的时间点信息是在生成event的时候产生的），为了方便大家阅读，后续内容将对binlog做分段说明。

（1）解析binlog

[root@localhost binlog]# mysqlbinlog -vv mysql-bin.000460 
......

（2）以下内容为binlog文件头，event 时间点为手工滚动binlog的时间点2018-10-04 15:31:55，这里并未有任何变化。

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

（3) at 194 position，事务的第一个event，也就是用于记录事务的GTID的event，时间点为15:36:42，通过我们事务操作时记录的时间信息，该时间为执行commit语句的时间点15:36:42。

# at 194

#181004 15:36:42 server id 3306111 end_log_pos 259 CRC32 0x7971213c GTID last_committed=0   sequence_number=1   rbr_only=yes

/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;

SET @@SESSION.GTID_NEXT= 'ec123678-5e26-11e7-9d38-000c295e08a0:199337'/*!*/;

（4) at 259 position，事务的第二个event，也就是用于记录事务的begin;语句的event，时间点为15:35:21，通过我们事务操作时记录的时间信息，该时间为执行update语句的时间点 15:35:21，并不是执行begin;语句的时间点15:33:02，说明该event是在执行update语句时产生，并不是在执行begin;语句时产生的。

#181004 15:35:21 server id 3306111 end_log_pos 338 CRC32 0x4d3af767 Query thread_id=3   exec_time=0 error_code=0

SET TIMESTAMP=1538638521/*!*/;

SET @@session.pseudo_thread_id=3/*!*/;

SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;

SET @@session.sql_mode=1436549152/*!*/;

SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=1/*!*/;

/*!\C utf8 *//*!*/;

SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=83/*!*/;

SET @@session.lc_time_names=0/*!*/;

SET @@session.collation_database=DEFAULT/*!*/;

BEGIN

/*!*/;

（5）at 338 position，事务的第三个event，用于记录事务执行的原始SQL语句(需要启用参数：binlog_rows_query_log_events=ON)，时间点仍然是执行update语句的时间点(15:35:21)，说明该event也是在执行update语句时产生。

# at 338

#181004 15:35:21 server id 3306111 end_log_pos 398 CRC32 0x066200c5 Rows_query

# update sbtest1 set k=k+1 where id=21

（6）at 398 position，事务的第四个event，用于记录事务对应的操作表在内存中的映射ID，时间点仍然是执行update语句的时间点(15:35:21)，说明该event也是在执行update语句时产生。

# at 398

#181004 15:35:21 server id 3306111 end_log_pos 457 CRC32 0x020d3fcf Table_map: `sbtest`.`sbtest1` mapped to number 143

（7) at 457 position，事务的第五个event，用于记录事务的完整操作语句和数据记录，也就是真正在执行update语句做数据修改（时间点仍然是 15:35:21），说明该event也是在执行update语句时产生。

# at 457

#181004 15:35:21 server id 3306111 end_log_pos 761 CRC32 0xdcfd94ba Update_rows: table id 143 flags: STMT_END_F

BINLOG '

ucK1Wx1/cjIAPAAAAI4BAACAACR1cGRhdGUgc2J0ZXN0MSBzZXQgaz1rKzEgd2hlcmUgaWQ9MjHF

AGIG

ucK1WxN/cjIAOwAAAMkBAAAAAI8AAAAAAAEABnNidGVzdAAHc2J0ZXN0MQAEAwP+/gTuaP60AM8/

DQI=

ucK1Wx9/cjIAMAEAAPkCAAAAAI8AAAAAAAEAAgAE///wFQAAABXlJQB3ADA5Mjc5MjEwMjE5LTM3

NzQ1ODM5OTA4LTU2MTg1Njk5MzI3LTc5NDc3MTU4NjQxLTg2NzExMjQyOTU2LTYxNDQ5NTQwMzky

LTQyNjIyODA0NTA2LTYxMDMxNTEyODQ1LTM2NzE4NDIyODQwLTExMDI4ODAzODQ5A3h4ePAVAAAA

FuUlAHcAMDkyNzkyMTAyMTktMzc3NDU4Mzk5MDgtNTYxODU2OTkzMjctNzk0NzcxNTg2NDEtODY3

MTEyNDI5NTYtNjE0NDk1NDAzOTItNDI2MjI4MDQ1MDYtNjEwMzE1MTI4NDUtMzY3MTg0MjI4NDAt

MTEwMjg4MDM4NDkDeHh4upT93A==

'/*!*/;

### UPDATE `sbtest`.`sbtest1`

### WHERE

### @1=21 /* INT meta=0 nullable=0 is_null=0 */

### @2=2483477 /* INT meta=0 nullable=0 is_null=0 */

### @3='09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849' /* STRING(360) meta=61032 nullable=0 is_null=0 */

### @4='xxx' /* STRING(180) meta=65204 nullable=0 is_null=0 */

### SET

### @1=21 /* INT meta=0 nullable=0 is_null=0 */

### @2=2483478 /* INT meta=0 nullable=0 is_null=0 */

### @3='09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849' /* STRING(360) meta=61032 nullable=0 is_null=0 */

### @4='xxx' /* STRING(180) meta=65204 nullable=0 is_null=0 */

（8）at 761 position，事务的第六个event，用于记录事务的commit语句，时间点为15:36:42，通过我们事务操作时记录的时间信息，该时间为执行commit语句的时间点15:36:42，说明该event是在执行commit语句时产生的。

# at 761

#181004 15:36:42 server id 3306111 end_log_pos 792 CRC32 0x3ad66423 Xid = 30

COMMIT/*!*/;

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解析内容中，用户事务的event有GTID(记录事务GTID)、Query（记录事务begin;语句）、Rows_query(在row格式下记录事务原始SQL语句)、Table_map（记录事务操作表在内存中的映射ID）、Update_rows（记录事务真正操作的语句和修改的具体数据记录）、xid（记录事务commit；语句）几种类型，其中：

（1）GTID和xid类型的event是在事务执行commit语句时产生的

（2）Query、Rows_query、Table_map、Update_rows 类型的event是在事务执行update 语句时产生的

（3）执行begin;语句时未产生任何event

本案例分析到此结束，留一个思考题给大家吧(大家可以依样画葫芦)。如果是主从架构，那么：

（1）从库的relay log中的event时间点会不会与主库binlog中记录的相同事务（这里指GTID相同）event时间点不同？

（2）从库如果启用了log_slave_updates=ON参数，从库自身的binlog中记录的复制事务的event会不会与主库binlog中记录的相同事务（这里指GTID相同） event时间点不同？

（3）如果主库存在并发事务，那么主库的binlog中记录的event时间点又是怎样的呢？

原文发布时间为：2018-12-11
本文作者：罗小波
本文来自云栖社区合作伙伴“ 老叶茶馆”，了解相关信息可以关注“iMySQL_WX”微信公众号

文章标签：
云数据库 RDS MySQL 版
云解析DNS
Python
数据库
关系型数据库
运维
MySQL
关键词：
binlog事务
binlog event
相关实践学习
如何快速连接云数据库RDS MySQL
本场景介绍如何通过阿里云数据管理服务DMS快速连接云数据库RDS MySQL，然后进行数据表的CRUD操作。
全面了解阿里云能为你做什么
阿里云在全球各地部署高效节能的绿色数据中心，利用清洁计算为万物互联的新世界提供源源不断的能源动力，目前开服的区域包括中国（华北、华东、华南、香港）、新加坡、美国（美东、美西）、欧洲、中东、澳大利亚、日本。目前阿里云的产品涵盖弹性计算、数据库、存储与CDN、分析与搜索、云通信、网络、管理与监控、应用服务、互联网中间件、移动服务、视频服务等。通过本课程，来了解阿里云能够为你的业务带来哪些帮助     相关的阿里云产品：云服务器ECS 云服务器 ECS（Elastic Compute Service）是一种弹性可伸缩的计算服务，助您降低 IT 成本，提升运维效率，使您更专注于核心业务创新。产品详情: https://www.aliyun.com/product/ecs
技术小能手
目录
相关文章
诸葛子房
|
7月前
|
缓存 关系型数据库 MySQL
MySQL Binlog--事务日志和BINLOG落盘参数对磁盘IO的影响
MySQL Binlog--事务日志和BINLOG落盘参数对磁盘IO的影响
诸葛子房
151 0
姚远OracleACE
|
SQL 小程序 前端开发
一个python小程序找出binlog中的大事务，一个update生成了1.4G的日志和65万条记录
base64-output参数用来控制binlog部分是否显示出来的，指定为decode-rows表示不显示binglog部分
姚远OracleACE
177 0
科技小先锋
|
SQL 关系型数据库 MySQL
MySQl binlog：row event释疑
科技小先锋
2406 0
余二五
|
Web App开发 关系型数据库 MySQL
MySQL binlog event 详解
余二五
1515 0
余二五
|
MySQL 关系型数据库
MySQL通过内部XA事务,保持了binlog与redo log之间数据一致性
余二五
1451 0
db匠
|
SQL 关系型数据库 MySQL
数据库内核月报 － 2015 / 06-MySQL · 答疑解惑 · binlog event 中的 error code
db匠
2099 0
db匠
|
关系型数据库 MySQL
MySQL内核月报 2014.12-MySQL·　答疑释惑·binlog event有序性
db匠
2724 0
智物科技库
|
25天前
|
存储 SQL 关系型数据库
mysql 的ReLog和BinLog区别
MySQL中的重做日志和二进制日志是确保数据库稳定性和可靠性的关键组件。重做日志主要用于事务的持久性和原子性，通过记录数据页的物理修改信息来恢复未提交的事务；而二进制日志记录SQL语句的逻辑变化，支持数据复制、恢复和审计。两者在写入时机、存储方式及配置参数等方面存在显著差异。
智物科技库
44 6
东方睿赢
|
3月前
|
canal 消息中间件 关系型数据库
Canal作为一款高效、可靠的数据同步工具，凭借其基于MySQL binlog的增量同步机制，在数据同步领域展现了强大的应用价值
【9月更文挑战第1天】Canal作为一款高效、可靠的数据同步工具，凭借其基于MySQL binlog的增量同步机制，在数据同步领域展现了强大的应用价值
东方睿赢
858 4
土木林森
|
4月前
|
SQL 关系型数据库 MySQL
【揭秘】MySQL binlog日志与GTID：如何让数据库备份恢复变得轻松简单？
【8月更文挑战第22天】MySQL的binlog日志记录数据变更，用于恢复、复制和点恢复；GTID为每笔事务分配唯一ID，简化复制和恢复流程。开启binlog和GTID后，可通过`mysqldump`进行逻辑备份，包含binlog位置信息，或用`xtrabackup`做物理备份。恢复时，使用`mysql`命令执行备份文件，或通过`innobackupex`恢复物理备份。GTID模式下的主从复制配置更简便。
土木林森
568 2