binlog 异常暴涨分析

最新推荐文章于 2021-03-29 09:20:33 发布
最新推荐文章于 2021-03-29 09:20:33 发布
阅读量286 收藏 1
点赞数
文章标签： 数据库

这是一个朋友遇到的问题，他的现象大概如下（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讲》中说明了，有兴趣可以关注一下：
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讲》中已经多次提到，这里就不在赘述了。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/7728585/viewspace-2652664/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/7728585/viewspace-2652664/

cri5768
关注
  • 0
    点赞
  • 踩
  • 1
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
MySQL Binlog Digger 4.28 + Mysql Binlog分析 + 数据库
08-19
MySQL Binlog Digger是一款免费的，且基于图形界面的binlog挖掘分析工具与sql审计工具。当发生误删、误增、误改时，它可以帮助我们从binlog中快速定位到误操作的重做语句(redo sql)，同时推理出回滚语句(undo sql)。...
Mysql大字段的频繁更新导致binlog暴增
weixin_34189116的博客
08-06 1281
2019独角兽企业重金招聘Python工程师标准>>> ...
记一次mysql binlog 撑爆磁盘处理过程
myy1066883508的博客
04-23 844
mysql> show binary logs; #获取binlog文件列表 mysql> show master status； #查看当前正在写入的binlog文件（除了这个文件其他的都可以删除） mysql> purge binary logs to “mysql-bin.000012”; 这里清楚12之前的文件（这里删除后再mysql binlog 存放目录下对...
线上mysql的binlog导致磁盘暴增的排查记录
oMaFei的博客
03-29 989
事情由来： 一大早突然收到zabbix告警，说磁盘就剩不到15了，赶紧上去瞅瞅什么情况 排查过程 1、df -ah 看看确认是/data目录占用91%了已经 2、找到具体/data下的哪个目录用的，最终定位到是mysql的binlog占用，这很明显是binlog写的太多导致的了，ps， 这里排查过程那个图忘了截了，可以用du -ah -d 1 看具体某个目录下的所有子目录的占用大小 -d 是代...
一次binlog暴涨的分析
liuzhilong的博客
01-14 598
某库最近binlog暴涨，撑到备份磁盘告警。几分钟就生成了500m，但是data文件不怎么涨 -rw-rw---- 1 mysql mysql 525780067 Jan 14 09:27 mysql-bin.002058 -rw-rw---- 1 mysql mysql 525172203 Jan 14 09:32 mysql-bin.002059 -rw-rw---- 1 mysql mysql 524929124 Jan 14 09:38 mysql-bin.002060 -rw-rw---- 1
binlog_transaction_dependency_tracking
Data & Analysis
01-04 1893
控制事务依赖模式，让从库根据主库写入binlog中的 commit timestamps 或者 write sets 并行回放事务（引入该参数之后，binlog的格式记录的内容中增加了时间戳和write sets信息） 有三个取值： COMMIT_ORDERE：使用 5.7 本来就支持的Group commit 的方式决定事务依赖 WRITESET：使用 WriteSet 的方式决定判定事务直接的冲突，发现冲突则依赖冲突事务，否则按照 COMMIT_ORDERE 方式决定依赖 WRITES
MySQL Binlog Digger 4.17.zip
11-08
MySQL Binlog Digger是一个免费的，且基于图形界面的binlog挖掘分析工具。它可以为数据恢复提供有力的参考依据，它可以对在线binlog与离线binlog进行挖掘分析，在设定过滤条件后便可以进行精确过滤，从而得到我们所...
PHP分析Mysql的Binlog日志并恢复数据
10-29
由于mysqlbinlog命令下无法筛选出某一个表的数据所以只能把日志文件全部导出
分析 MySQL 的 binlog 日志的工具
06-03
作为一个MySQL DBA，查看分析binlog是日常工作的一部分，不知道你是否遇到过这样的需求：一个时间段，各个表的dml统计情况
MySQL binlog_transaction_dependency_tracking=commit_order和slave_preserve_commit_order的区别
灯火觅阑珊
11-12 5485
binlog_transaction_dependency_tracking是设在主库，可以取commit_order,writeset,writeset_session，主要是控制binlog文件中last_committed的计算方式： commit_order即group commit，同在prepare阶段的事务，在binlog中last_committed数值一样，传到从库之后可以并行执...
mysql binlog急速增长_MYSQL中如何实现binlog优化
weixin_33417488的博客
01-19 925
MYSQL中如何实现binlog优化发布时间：2020-07-17 10:27:49来源：亿速云阅读：102作者：小猪这篇文章主要讲解了MYSQL中如何实现binlog优化，内容清晰明了，对此有兴趣的小伙伴可以学习一下，相信大家阅读完之后会有帮助。问题问题1：如何解决事务提交时flush redo log带来的性能损失WAL是实现事务持久性(D)的一个常用技术，基本原理是将事务的修改记录redo ...
技术分享 | binlog 异常暴涨分析
chiweiliu4439的博客
08-23 333
原创作者：高鹏 背景 这是一个朋友遇到的问题，他的现象大概如下（MySQL5.6）： 某个binlog实际大小3g左右，实际设置大小应该是1g 其中包含一个大事务，但是最后一个事务是小事务 查看大事务的XID_EVENT（'commit'）时间和最后一个小事...
mysql的binlog太大
buyue
01-03 2205
现象：网站访问越来越慢，最后无法访问了，经过检查发现磁盘满了。仔细查询下来确认是由于mysql的binlog太多太大占用了空间。 分析过程及解决方案：通常出现这种问题都应该登录服务器检查磁盘、内存和进程使用的情况，通过top、df –h和free –m来检查，发现磁盘空间满了。 再进一步通过du –sh对可以的目录进行检查，发现是mysql的binlog占用空间过大。 清理binlog的
mysql的binlog太多太大占用了空间的解决办法
weixin_30652491的博客
05-30 484
现象：网站访问越来越慢，最后无法访问了，经过检查发现磁盘满了 分析过程及解决方案：通常出现这种问题都应该登录服务器检查磁盘、内存和进程使用的情况，通过top、df –h和free –m来检查，发现磁盘空间满了。再进一步通过du –sh对可以的目录进行检查，发现是mysql的binlog占用空间过大。清理binlog的方法如下： 1)设置日志保留时长expire_logs_days自动删除...
RDS最佳实践(五)—Mysql大字段的频繁更新导致binlog暴增
weixin_33686714的博客
03-25 701
背景：RDS Mysql采用的binlog 格式默认为ROW，在Mysql 5.6的版本之前，Mysql每次列的修改（update）都需要记录表中所有列的值。这样就存在一个问题，如果表中包含很多的大字段，表的单行长度就会非常长，这样每次update就会导致大量的 binlog空间生成。针对这个问题，在mysql 5.6中进行了改进，复制支持”row im...
mysql binlog急速增长_mysqlbinlog增量恢复
weixin_35767900的博客
01-27 880
前言mysqlbinlog工具的作用是解析mysql的二进制binlog的日志内容，把二进制日志解析成可以在MySQL数据库里执行的SQL语句。1.mysql的binlog日志是什么mysql数据目录下的xxx-bin.000001这样的文件就是mysql的binlog日志2.mysql的binlog日志的作用mysql的binlog日志用于记录MySQL内部的增删改等操作，也就是对MySQL数据...
mysql binlog生成异常_MySQL中遇到binlog 异常暴涨分析
weixin_33486249的博客
01-27 500
背景这是一个朋友遇到的问题，他的现象大概如下(MySQL5.6)：某个binlog实际大小3g左右，实际设置大小应该是1g其中包含一个大事务，但是最后一个事务是小事务查看大事务的XID_EVENT('commit')时间和最后一个小事务XID_EVENT('commit')时间差值近15分钟下面是他提供的依据：mysqlbinlog-vvmysqlbinlog_file>mysqlb...
mysql中的并发复制
敖尔其楞的专栏
11-07 801
mysql在几个大版本中的并发复制都不一样，当然做的是越来越好。 在5.6版本中 –slave-parallel-workers参数代表并行执行复制事务的slave worker线程的数量，设置未0代表禁用并行复制，最大值是1024.当并行执行设置后，sql线程充当了slave worker线程的调度器，事务是基于每个数据库的。就是基于库级别的， 由于是并发的就会导致，不同数据库上的事务在从库上应...
mysql binlog
最新发布
08-08
- 使用mysqlbinlogviewer等工具可以以可视化的方式查看和分析binlog。 请注意，使用binlog功能需要谨慎，因为它会产生大量的日志数据，可能会对数据库性能产生一定影响。同时，确保对binlog文件进行适当的备份和...

“相关推荐”对你有帮助么？

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

个

红包个数最小为10个

元

红包金额最低5元

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

抵扣说明：

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

余额充值