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

导 读

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

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文件

 
 
  1. root@localhost : sbtest 03:27:34> flush binary logs;select now();

  2. Query OK, 0 rows affected (0.01 sec)

  3. +---------------------+

  4. | now() |

  5. +---------------------+

  6. | 2018-10-04 15:31:55 |  # 滚动binlog的时间点为2018-10-04 15:31:55

  7. +---------------------+

  8. 1 row in set (0.00 sec)

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

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

  2. mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'

  3. /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;

  4. /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;

  5. DELIMITER /*!*/;

  6. # at 4

  7. #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

  8. # Warning: this binlog is either in use or was not closed properly.

  9. BINLOG '

  10. 68G1Ww9/cjIAdwAAAHsAAAABAAQANS43LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

  11. AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA

  12. ASgZxpw=

  13. '/*!*/;

  14. # at 123

  15. #181004 15:31:55 server id 3306111 end_log_pos 194 CRC32 0xc34422d7 Previous-GTIDs

  16. # ec123678-5e26-11e7-9d38-000c295e08a0:182318-199336

  17. SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;

  18. DELIMITER ;

  19. # End of log file

  20. /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

  21. /*!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是如何记录的。

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

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

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

  3. +----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+

  4. | id | k | c | pad |

  5. +----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+

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

  7. +----+---------+-------------------------------------------------------------------------------------------------------------------------+-----+

  8. 1 row in set (0.00 sec)

  9. # 显式开启一个事务

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

  11. Query OK, 0 rows affected (0.00 sec)

  12. +---------------------+

  13. | now() |

  14. +---------------------+

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

  16. +---------------------+

  17. 1 row in set (0.00 sec)

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

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

  2. Query OK, 1 row affected (0.00 sec)

  3. Rows matched: 1 Changed: 1 Warnings: 0

  4. +---------------------+

  5. | now() |

  6. +---------------------+

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

  8. +---------------------+

  9. 1 row in set (0.00 sec)

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

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

  2. Query OK, 0 rows affected (0.01 sec)

  3. +---------------------+

  4. | now() |

  5. +---------------------+

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

  7. +---------------------+

  8. 1 row in set (0.00 sec)


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

(1)解析binlog

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

  2. ......

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

 
 
  1. mysqlbinlog: [Warning] unknown variable 'loose_default-character-set=utf8'

  2. /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;

  3. /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;

  4. DELIMITER /*!*/;

  5. # at 4

  6. #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

  7. # Warning: this binlog is either in use or was not closed properly.

  8. BINLOG '

  9. 68G1Ww9/cjIAdwAAAHsAAAABAAQANS43LjIwLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA

  10. AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA

  11. ASgZxpw=

  12. '/*!*/;

  13. # at 123

  14. #181004 15:31:55 server id 3306111 end_log_pos 194 CRC32 0xc34422d7 Previous-GTIDs

  15. # ec123678-5e26-11e7-9d38-000c295e08a0:182318-199336

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

 
 
  1. # at 194

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

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

  4. 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;语句时产生的。

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

  2. SET TIMESTAMP=1538638521/*!*/;

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

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

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

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

  7. /*!\C utf8 *//*!*/;

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

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

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

  11. BEGIN

  12. /*!*/;

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

 
 
  1. # at 338

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

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

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

 
 
  1. # at 398

  2. #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语句时产生。

 
 
  1. # at 457

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

  3. BINLOG '

  4. ucK1Wx1/cjIAPAAAAI4BAACAACR1cGRhdGUgc2J0ZXN0MSBzZXQgaz1rKzEgd2hlcmUgaWQ9MjHF

  5. AGIG

  6. ucK1WxN/cjIAOwAAAMkBAAAAAI8AAAAAAAEABnNidGVzdAAHc2J0ZXN0MQAEAwP+/gTuaP60AM8/

  7. DQI=

  8. ucK1Wx9/cjIAMAEAAPkCAAAAAI8AAAAAAAEAAgAE///wFQAAABXlJQB3ADA5Mjc5MjEwMjE5LTM3

  9. NzQ1ODM5OTA4LTU2MTg1Njk5MzI3LTc5NDc3MTU4NjQxLTg2NzExMjQyOTU2LTYxNDQ5NTQwMzky

  10. LTQyNjIyODA0NTA2LTYxMDMxNTEyODQ1LTM2NzE4NDIyODQwLTExMDI4ODAzODQ5A3h4ePAVAAAA

  11. FuUlAHcAMDkyNzkyMTAyMTktMzc3NDU4Mzk5MDgtNTYxODU2OTkzMjctNzk0NzcxNTg2NDEtODY3

  12. MTEyNDI5NTYtNjE0NDk1NDAzOTItNDI2MjI4MDQ1MDYtNjEwMzE1MTI4NDUtMzY3MTg0MjI4NDAt

  13. MTEwMjg4MDM4NDkDeHh4upT93A==

  14. '/*!*/;

  15. ### UPDATE `sbtest`.`sbtest1`

  16. ### WHERE

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

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

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

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

  21. ### SET

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

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

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

  25. ### @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语句时产生的。

 
 
  1. # at 761

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

  3. COMMIT/*!*/;

  4. SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;

  5. DELIMITER ;

  6. # End of log file

  7. /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

  8. /*!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时间点又是怎样的呢?


640.gif?


加入知数堂

挑战40万+年薪!



640?640?640?640?


知数堂

叶金荣与吴炳锡联合打造

领跑IT精英培训

行业资深专家强强联合,倾心定制

MySQL实战/MySQL优化/MongoDB/

Python/ SQL优化/Hadoop+ELK

数门精品课程

“阅读原文”可获更多正课试听视频

密码:hg3h

紧随技术发展趋势,定期优化培训教案

融入大量生产案例,贴合企业一线需求

社群陪伴学习,一次报名,可学1年

DBA、开发工程师必修课

上千位学员已华丽转身,薪资翻番,职位提升

改变已悄然发生,你还在等什么?

640.png?



640?wx_fmt=gif 扫码加入QQ技术交流群

MySQL 8.0|MGR研究院-ZST

(QQ群号:650149401)    

640?wx_fmt=jpeg


评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值