专栏首页SEian.G学习记录MySQL中Binlog日志应用慢,该怎么办?

MySQL中Binlog日志应用慢,该怎么办?

今天有一个业务需求,需要进行数据恢复操作,需要恢复到2021-07-11 15:21:00,大家应该都了解,这种基于时间点的恢复,首先通过物理备份将mysql全量恢复到异机中,然后再进行增量恢复binlog,从而实现基于时间点的恢复;

业务环境数据量大小150G左右,按照之前做的大量的随机恢复测试总时间分析看,150G的数据量恢复大概可以控制在30min内完成;

正常情况下,1G的binlog应用时间大概在1~3min左右,但是在本次恢复应用binlog的过程,花费了将近15min还没有结束,导致整个恢复时间40多分钟还没有结束;这种情况别说业务人员不能接受,作为DBA估计不能接受吧!

下面就来就针对Binlog回放慢的问题做一个简单的分析:

问题现象:

登录到恢复实例上看一下目前的应用状态,查看到线程目前一直处于Waiting for GTID to be committed的状态,从该状态看,是在等待GTID提交,GTID为548723ca-1f7f-11e9-b3ab-005056b748c5:1655852015

mysql>show processlist;
+----+-----------+-----------------+------+---------+--------+----------------------------------+----------------------------------------------------------------------------+-----------+---------------+
| Id | User      | Host            | db   | Command | Time   | State                            | Info                                                                       | Rows_sent | Rows_examined |
+----+-----------+-----------------+------+---------+--------+----------------------------------+----------------------------------------------------------------------------+-----------+---------------+
|  6 | dba_admin | 127.0.0.1:6492  | NULL | Sleep   | 218132 |                                  | NULL                                                                       |         0 |             0 |
| 16 | dba_admin | 127.0.0.1:11286 | NULL | Query   | 218078 | Waiting for GTID to be committed | SET @@SESSION.GTID_NEXT= '548723ca-1f7f-11e9-b3ab-005056b748c5:1655852015' |         0 |             0 |
| 17 | dba_admin | 127.0.0.1:11294 | NULL | Query   |      0 | starting                         | show processlist                                                           |         0 |             0 |
+----+-----------+-----------------+------+---------+--------+----------------------------------+----------------------------------------------------------------------------+-----------+---------------+
3 rows in set (0.00 sec)

问题分析:

1、首先检查恢复机资源使用情况,特别是IO,经过查看 ,发现恢复机的负载非常的低,资源非常的空闲,所以应该不是资源繁忙导致的

2、那有可能是大事务导致binlog应用的比较慢,接下来分析下binlog的中是否有大事务

$ mysqlbinlog mysqlbin.002032 | grep "GTID$(printf '\t')last_committed" -B 1 | grep -E '^# at' | awk '{print $3}'| awk 'NR==1 {tmp=$1} NR>1 {print ($1-tmp);tmp=$1}'| sort -n -r | head -n 10
mysqlbinlog: [Warning] unknown variable 'loose-default-character-set=utf8'
203995532
518143
518103
518055
518045
518043
518037
518035
518033
518023

从结果看,竟然有一个200M的大事务,我的天哪,估计就是这个大事务导致回放比较慢,那到底是不是这个大事务导致的呢?

3、 接下来根据长时间运行线程状态提供的GTID的信息,解析下binlog文件查看下卡主的GTID事务具体在执行什么操作?

# at 156880949
#210711  2:00:05 server id 255  end_log_pos 156881014 CRC32 0x9c02b320  GTID    last_committed=127167   sequence_number=127168
SET @@SESSION.GTID_NEXT= '548723ca-1f7f-11e9-b3ab-005056b748c5:1655852015'/*!*/;
# at 156881014
#210711  2:00:05 server id 255  end_log_pos 156881077 CRC32 0xf27b8fdc  Query   thread_id=55553520      exec_time=54    error_code=0
SET TIMESTAMP=1625940005/*!*/;
BEGIN
/*!*/;
# at 156881077
#210711  2:00:05 server id 255  end_log_pos 156881203 CRC32 0xf297d5f2  Rows_query
# delete from tabname where create_time <= date_sub(CURRENT_TIMESTAMP, interval 24 hour)
# at 156881203
#210711  2:00:05 server id 255  end_log_pos 156881301 CRC32 0xa101984d  Table_map: `test_db`.`tabname` mapped to number 110
# at 156881301
#210711  2:00:05 server id 255  end_log_pos 156889457 CRC32 0xbe518068  Delete_rows: table id 110
# at 156889457
#210711  2:00:05 server id 255  end_log_pos 156897608 CRC32 0x54e957f0  Delete_rows: table id 110
# at 156897608
#210711  2:00:05 server id 255  end_log_pos 156905781 CRC32 0x8d2612ad  Delete_rows: table id 110
# at 156905781
#210711  2:00:05 server id 255  end_log_pos 156913928 CRC32 0xb15a94ea  Delete_rows: table id 110
# at 156913928
#210711  2:00:05 server id 255  end_log_pos 156922097 CRC32 0x6393fa7c  Delete_rows: table id 110
# at 156922097
#210711  2:00:05 server id 255  end_log_pos 156930266 CRC32 0x2b3d1fda  Delete_rows: table id 110
# at 156930266
#210711  2:00:05 server id 255  end_log_pos 156938414 CRC32 0x78874052  Delete_rows: table id 110
# at 156938414
#210711  2:00:05 server id 255  end_log_pos 156946567 CRC32 0xb67779fe  Delete_rows: table id 110
# at 156946567
#210711  2:00:05 server id 255  end_log_pos 156954729 CRC32 0x0c0f8899  Delete_rows: table id 110
# at 156954729
#210711  2:00:05 server id 255  end_log_pos 156962870 CRC32 0x5f79436d  Delete_rows: table id 110
.......

从解析后的binlog可以发现,是一个delete操作, delete from tabname where create_time <= date_sub(CURRENT_TIMESTAMP, interval 24 hour),该SQL删除24小时之前的所有数据,而该操作正是那个200M的事务,到这里就知道了具体的原因,那么该问题该如何解决呢?

解决方案:

1、那就接着等呗,总会应用结束,这你能接受,业务人员估计也是不能接受的;

2、临时调整sync_binlog和innodb_flush_log_at_trx_commit参数,从双1调整成0,之后回放速度就会快很多;

备注:反正是在异机恢复,安全不是重要的,线上环境谨慎考虑;

最后,找业务人员沟通确认该操作的合理性,业务侧将一个大事务拆分成多个小事务执行;

好了,就先说这么多吧,大家有更好的方法欢迎留言一起学习交流;

本文分享自微信公众号 - DBA的辛酸事儿(dbabitter),作者:SEianG

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

原始发表时间:2021-07-15

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

我来说两句

0 条评论
登录 后参与评论

相关文章

  • 20个【MySQL】经典面试题

    一个6亿的表a,一个3亿的表b,通过外间tid关联,你如何最快的查询出满足条件的第50000到第50200中的这200条数据记录。

    lyb-geek
  • Mysql数据库之Binlog日志使用总结

    binlog二进制日志对于mysql数据库的重要性有多大,在此就不多说了。下面根据本人的日常操作经历,并结合网上参考资料,对binlog日志使用做一梳理: 一、...

    洗尽了浮华
  • Mysql优化方面的面试题

    本文是个人在各种地方收集过来,包括自己总结的问题,都参杂在内,适合中级或者中上级开发面试的难度。

    胖虎
  • 关于主从延迟,一篇文章给你讲明白了!

    在实际的生产环境中,由单台MySQL作为独立的数据库是完全不能满足实际需求的,无论是在安全性,高可用性以及高并发等各个方面

    MySQL技术
  • 面试BAT前先搞定这18道MySQL经典面试题(含答案解析)

    1. 主:binlog线程——记录下所有改变了数据库数据的语句,放进master上的binlog中;

    程序员追风
  • 原来MySQL面试还会问这些...

    在前一阵子,大哥问过我:”你知道MySQL的原子性是怎么保证的吗“。我懵逼了,MySQL怎么保证原子性?我不会啊。

    乔戈里
  • 第31问:慢日志觉得一个 SQL 很慢,但 binlog 不这么觉得,怎么办?

    首先在 binlog 中,发现这条 SQL 运行了 2 秒。(上一问中, 我们知道 BEGIN 的 exec_time 等于事务第一个 SQL 的 exec_t...

    爱可生开源社区
  • “大”事务引起的锁等待分析案例

    生产环境数据库在某一刻突然发现大量活跃连接,而且大部分状态是updating。问题出现在周六上午,持续了大概三、四分钟,得益于我们自己的快照程序,拿到了当时现场...

    wubx
  • MySql主从复制

    在MySql的生产环境中,由于单台MySql不能满足高可用性需求,一般通过主从复制(Master-Slave)方式同步数据,再通过读写分离(MySql-Prox...

    春哥大魔王
  • “大”事务引起的锁等待分析案例

    生产环境数据库在某一刻突然发现大量活跃连接,而且大部分状态是updating。问题出现在周六上午,持续了大概三、四分钟,得益于我们自己的快照程序,拿到了当时现场...

    wubx
  • MySQL 日志之 binlog 格式 → 关于 MySQL 默认隔离级别的探讨

      在讲 binlog 之前,我们先来回顾下主流关系型数据库的默认隔离级别,是默认隔离级别,不是事务有哪几种隔离级别,别会错题意了

    青石路
  • 万字分享,我是如何一步一步监控公司MySQL的?

    在家远程办公第三周,快被手机上的消息搞的有些神经质了,生怕错过一条有用的信息,没办法形势如此,公司摇摇欲坠大家也都如履薄冰,毕竟这时候失业有点惨(穷怕了)。

    程序员内点事
  • MySQL 主从复制的问题及解决方案

    MySQL 主从复制的问题及解决方案

    Java架构师必看
  • 删库跑路不怕,用mysqldump和mysqlbinlog进行数据恢复

    1.创建douyin数据库、tbl_douyin_author数据库表、插入测试数据。

    用户2032165
  • mysql主从同步(2)-问题梳理

    之前部署了Mysql主从复制环境(Mysql主从同步(1)-主从/主主环境部署梳理),在mysql同步过程中会出现很多问题,导致数据同步异常。 以下梳理了几种主...

    洗尽了浮华
  • 重新学习MySQL数据库10:MySQL里的那些日志们

    本文是微信公众号【Java技术江湖】的《重新学习MySQL数据库》其中一篇,本文部分内容来源于网络,为了把本文主题讲得清晰透彻,也整合了很多我认为不错的技术博客...

    Java技术江湖
  • MySQL读写分离一遇高并发访问,所有服务瞬间集体罢工,问题解决如坐过山车,太刺激了

    最近系统(基于 SpringCloud + K8s)上线,运维团队早上 8 点左右在群里反馈,系统登录无反应!我的第一反应是 MySQL 数据库扛不住了。

    猿芯
  • MySQL案例:一个有趣的慢查询问题分析

    前几天,有位客户提了一个慢查询问题,需要这边帮忙分析一下;整个排查过程还是非常有趣,涉及到一些值得关注的知识点,因此在这里记录一下。

    brightdeng@DBA
  • 史上最详细的一线大厂Mysql面试题详解

    主:binlog线程——记录下所有改变了数据库数据的语句,放进master上的binlog中;

    用户4447430

扫码关注云+社区

领取腾讯云代金券