binlog 异常暴涨分析

本文涉及的产品
RDS MySQL Serverless 基础系列,0.5-2RCU 50GB
RDS MySQL Serverless 高可用系列,价值2615元额度,1个月
云数据库 RDS PostgreSQL,高可用系列 2核4GB
简介: 这是一个朋友遇到的问题,他的现象大概如下(MySQL5.6):某个binlog实际大小3g左右,实际设置大小应该是1g其中包含一个大事务,但是最后一个事务是小事务查看大事务的XID_EVENT(‘commit’)时间和最后一个小事务XID_EVENT(‘commit’)时间差值近15分钟...

这是一个朋友遇到的问题,他的现象大概如下(MySQL5.6):

  • 某个binlog实际大小3g左右,实际设置大小应该是1g
  • 其中包含一个大事务,但是最后一个事务是小事务
  • 查看大事务的XID_EVENT(‘commit’)时间和最后一个小事务XID_EVENT(‘commit’)时间差值近15分钟

下面是他提供的依据:


mysqlbinlog -vv mysqlbinlog_file > mysqlbinlog_res.log
grep -n -B 1 "COMMIT" mysqlbinlog_res.log > file.log
tar zcf file.log.tar.gz file.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分钟之多呢?

实际上这些问题的原因我都在我的《深入理解MySQL主从原理 32讲》中说明了,有兴趣可以关注一下:

image.png

好了下面我们来实际分析一下。

一、提交流程图

这张图是《深入理解MySQL主从原理 32讲》中第15节的截取如下,当然这个图是基于MySQL5.7.22画的:

15-1.png

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

二、为什么大事务会包含在一个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分钟,那么如下:

大事务flush T1
大事务sync开始 T2 小事务flush T2
小事务flush T3
小事务flush T4
大事务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左右:

image.png

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

### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
### DELETE FROM `testmts`.`testnnn`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
# at 3626617
#190804 22:56:10 server id 413340  end_log_pos 3626648 CRC32 0xfc5b79e7         Xid = 143
COMMIT/*!*/;
# at 3626648
#190804 23:02:26 server id 413340  end_log_pos 3626713 CRC32 0xa2399157         GTID    last_committed=0        sequence_number=2       rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'cb7ea36e-670f-11e9-b483-5254008138e4:191'/*!*/;
# at 3626713
#190804 23:02:26 server id 413340  end_log_pos 3626788 CRC32 0x555fb49d         Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1564930946/*!*/;
BEGIN
/*!*/;
# at 3626788
#190804 23:02:26 server id 413340  end_log_pos 3626838 CRC32 0xec0a4316         Table_map: `testmts`.`tm10` mapped to number 149
# at 3626838
#190804 23:02:26 server id 413340  end_log_pos 3626878 CRC32 0x61c79d68         Delete_rows: table id 149 flags: STMT_END_F
### DELETE FROM `testmts`.`tm10`
### WHERE
###   @1=10 /* INT meta=0 nullable=1 is_null=0 */
# at 3626878
#190804 23:02:26 server id 413340  end_log_pos 3626909 CRC32 0x2a9cd136         Xid = 154
COMMIT/*!*/;
# at 3626909
#190804 23:02:26 server id 413340  end_log_pos 3626974 CRC32 0x06b081ec         GTID    last_committed=0        sequence_number=3       rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'cb7ea36e-670f-11e9-b483-5254008138e4:192'/*!*/;
# at 3626974
#190804 23:02:26 server id 413340  end_log_pos 3627049 CRC32 0x0e214995         Query   thread_id=5     exec_time=1     error_code=0
SET TIMESTAMP=1564930946/*!*/;
BEGIN
/*!*/;
# at 3627049
#190804 23:02:26 server id 413340  end_log_pos 3627104 CRC32 0x8ee0af93         Table_map: `testmts`.`tmpk` mapped to number 150
# at 3627104
#190804 23:02:26 server id 413340  end_log_pos 3627154 CRC32 0x4804be49         Delete_rows: table id 150 flags: STMT_END_F
### DELETE FROM `testmts`.`tmpk`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='g' /* VARSTRING(60) meta=60 nullable=1 is_null=0 */
###   @3=1 /* INT meta=0 nullable=1 is_null=0 */
###   @4=1 /* INT meta=0 nullable=1 is_null=0 */
# at 3627154
#190804 23:02:26 server id 413340  end_log_pos 3627185 CRC32 0x64f2ea15         Xid = 153
COMMIT/*!*/;

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

[root@mysqltest2 log]# cat -n log.log|grep last
    11  #190804 22:56:10 server id 413340  end_log_pos 299 CRC32 0x47602f13     
GTID    last_committed=0        sequence_number=1       rbr_only=yes
2167349 #190804 23:02:26 server id 413340  end_log_pos 3626713 CRC32 0xa2399157         
GTID    last_committed=0        sequence_number=2       rbr_only=yes
2167368 #190804 23:02:26 server id 413340  end_log_pos 3626974 CRC32 0x06b081ec         
GTID    last_committed=0        sequence_number=3       rbr_only=yes

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

六、注意

最后需要提醒一下,MySQL不要有过大的事务,我觉得大事务最大的危害在于会堵塞整个数据库其他事务的提交,这个在我的《深入理解MySQL主从原理 32讲》中已经多次提到,这里就不在赘述了。

作者微信:gp_22389860

相关实践学习
每个IT人都想学的“Web应用上云经典架构”实战
本实验从Web应用上云这个最基本的、最普遍的需求出发,帮助IT从业者们通过“阿里云Web应用上云解决方案”,了解一个企业级Web应用上云的常见架构,了解如何构建一个高可用、可扩展的企业级应用架构。
MySQL数据库入门学习
本课程通过最流行的开源数据库MySQL带你了解数据库的世界。   相关的阿里云产品:云数据库RDS MySQL 版 阿里云关系型数据库RDS(Relational Database Service)是一种稳定可靠、可弹性伸缩的在线数据库服务,提供容灾、备份、恢复、迁移等方面的全套解决方案,彻底解决数据库运维的烦恼。 了解产品详情: https://www.aliyun.com/product/rds/mysql 
相关文章
|
SQL 关系型数据库 MySQL
如何使用MySQL Binlog Digger 4.14对binlog日志进行挖掘分析以便快速恢复误删除数据
MySQL Binlog Digger是一款运行在windows操作系统的挖掘与分析MySQL binlog的可视化工具,通过它可以快速打回被误操作时的数据,例如:delete, insert, update操作,并依据这些误操作生成相应的undo回滚语句,以便快速恢复数据,此外,它还可以支持离线binlog挖掘分析与binlog下载,它仅支持dml操作的回滚,但不支持ddl的回滚。
4688 1
如何使用MySQL Binlog Digger 4.14对binlog日志进行挖掘分析以便快速恢复误删除数据
|
资源调度 Kubernetes Java
实时计算 Flink版产品使用问题之全量快照初始化时,如果任务异常自动从ck restore后,会从上次binlog断点续传吗
实时计算Flink版作为一种强大的流处理和批处理统一的计算框架,广泛应用于各种需要实时数据处理和分析的场景。实时计算Flink版通常结合SQL接口、DataStream API、以及与上下游数据源和存储系统的丰富连接器,提供了一套全面的解决方案,以应对各种实时计算需求。其低延迟、高吞吐、容错性强的特点,使其成为众多企业和组织实时数据处理首选的技术平台。以下是实时计算Flink版的一些典型使用合集。
|
SQL 存储 缓存
分析MySQL执行的流程(连接、缓存、分析、优化、执行、Undo Log、Binlog、Redo Log)
熟悉MySQL的都知道MySQL服务端实现主要分为Server层和存储引擎层。Server层负责接收和管理客户端连接、管理缓存、解析SQL、优化SQL、调用存储引擎执行SQL;存储引擎层主要负责存储、查询数据。
分析MySQL执行的流程(连接、缓存、分析、优化、执行、Undo Log、Binlog、Redo Log)
|
SQL 存储 关系型数据库
|
canal 缓存 关系型数据库
Canal binlog 日志 Dump 流程分析
Canal binlog 日志 Dump 流程分析
Canal binlog 日志 Dump 流程分析
|
监控 关系型数据库 数据库
10分钟搭建MySQL Binlog分析+可视化方案
日志服务 最近在原有30+种数据采集渠道 基础上,新增MySQL Binlog、MySQL select等数据库方案,仍然主打快捷、实时、稳定、所见即所得的特点。 以下我们以用户登录数据库作为案例,演示如何在10分钟内手把手完成从binlog采集到查询、告警、搭建报表等全过程,满足各个老板们的需求。
15172 0
10分钟搭建MySQL Binlog分析+可视化方案
|
存储 安全 关系型数据库
MySQL · 源码分析 · MySQL BINLOG半同步复制数据安全性分析
半同步复制(semisynchronous replication)MySQL使用广泛的数据复制方案,相比于MySQL内置的异步复制它保证了数据的安 全,本文从主机在Server层提交事务开始一直到主机确认收到备机回复进行一步步解析,来看MySQL的半同步复制是怎么保证数 据安全的。本文基于MySQL 5.6源码,为了简化本文只分析DML的核心的事务处理过程,并假定事务只涉及innodb存储引擎。
2992 1
|
SQL MySQL 关系型数据库
手动注册binlog文件造成主从异常
一、问题来源 有一个朋友@水米田 问我,基于POSITION的主从。他做了如下的操作 将备份的一些binlog文件加入到了目录中 修改index文件,加入了这些binlog文件 flush binary logs 然后整个主从环境大量延迟。
1193 0
|
SQL 关系型数据库 MySQL
MySQL · 捉虫动态 · 字符集相关变量介绍及binlog中字符集相关缺陷分析
MySQL字符集相关变量介绍及binlog中字符集相关缺陷分析 MySQL支持多种字符集(character set)提供用户存储数据,同时允许用不同排序规则(collation)做比较。 本文基于MySQL5.7介绍了字符集相关变量的使用,通过例子描述了这些变量具体意义。
8121 0