专栏首页idbabinlog 异常暴涨分析

binlog 异常暴涨分析

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

  • 某个binlog实际大小8g左右,实际设置大小应该是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讲》中说明了,有兴趣可以关注一下:(自带广告效果)

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

一、提交流程图

这张图是《深入理解MySQL主从原理 32讲》中第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分钟之多

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

对于自动事务提交,那么XIDEVENT会是命令发起的时间,因此更容易出现这种情况,后面会使用这种情况进行证明。对于显示开启事务‘begin commit’,那么XIDEVENT会是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:COMMITORDER,这是默认的配置,为了更好的证明我们前面生成同样的last commit的结论,避免writeset的干扰。

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

最后我们不使用通过‘begin commit’显示的开启事务,因为这样XIDEVENT的时间是commit命令发起的时间,也就不太容易重现案例中的这种XIDEVENT大事务和小事务时间相差很大现象。但是实际上如果事务足够大也是可以的,因为在大事务如案例中有几亿的数据那么这个事务的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的最后部分内容,我们可以发现最后两个事务均是小事务,大事务并不是最后一个事务如下:

### 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讲》中已经多次提到,这里就不在赘述了。有兴趣的朋友 可以扫码上车学习。

本文分享自微信公众号 - yangyidba(yangyidba),作者:高鹏

原文出处及转载信息见文内详细说明,如有侵权,请联系 yunjia_community@tencent.com 删除。

原始发表时间:2019-08-06

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

我来说两句

0 条评论
登录 后参与评论

相关文章

  • 图解MySQL | [原理解析] MySQL组提交(group commit)

    本文是由爱可生研发团队出品的「图解MySQL」系列文章,不定期更新,但篇篇精品。欢迎大家持续关注~

    用户1278550
  • MySQL-8.0 redo优化剖析

    redo_log的作用设计初衷为了提高写入性能同时解决ACID中Duration。MySQL 8.0对redo_log进行了无锁化设计,去除了redo_log性...

    用户1278550
  • 面试必备之乐观锁与悲观锁

    前几天研究 热点扣减场景的时候,比较深入的学习到无锁并发更新的常见算法 cas 的使用场景。本文是对CAS的自我学习笔记。

    用户1278550
  • 分布式事务解决方案FESCAR

    Fescar 是 阿里巴巴 开源的 分布式事务中间件,以 高效 并且对业务 0 侵入 的方式,解决 微服务 场景下面临的分布式事务问题。

    IT云清
  • 到底什么是分布式系统?

    微服务倡导将复杂的单体应用拆分为若干个功能简单、松耦合的服务,这样可以降低开发难度、增强扩展性、便于敏捷开发。当前被越来越多的开发者推崇,系统微服务化后,一个看...

    kubernetes中文社区
  • 分布式事务解决方案FESCAR

    以下是官网的文档。 简介 2019年,Fescar 是 阿里巴巴 开源的 分布式事务中间件,以 高效 并且对业务 0 侵入 的方式,解决 微服务 场景下面临的分...

    爱撸猫的杰
  • MySQL binlog

    【转载请注明出处】:https://cloud.tencent.com/developer/article/1632663

    后端老鸟
  • 客官来玩K8S之搭个Gitlab

    这里面用的 PV/PVC 需要自己在腾讯云里面创建, 基本就是点点点就能创建出来了.

    李国宝
  • PaperReading-用能力感知神经网络提高人岗匹配效果

    抛开这篇论文,我们先谈一谈人岗匹配这件事到底在做什么,做哪些难点。 一家大公司,一旦发布了某招聘需求,往往每天会有成千上万封简历飞来应聘。HR需要从这成千上万封...

    beyondGuo
  • Laravel 限制条数后再分页

    laravel 自带开箱即用的分页,使用起来如丝般顺滑。默认情况下是对所有记录进行分页,现在我们有这样的需求:限制用户只能看到前 30 页。第一想法就是用 li...

    章鱼喵

扫码关注云+社区

领取腾讯云代金券