MySQL主备延迟竟17小时了!然而可能还要等2年...

4,694 阅读6分钟

「这是我参与11月更文挑战的第5天,活动详情查看:2021最后一次更文挑战」。

本文讲述一个工作中真实发生的故事(事故:)。

故事发生

事情是这样的,很简单的一个开端:

binlog.png

  • 第1天:
    • 我在正常的编码,完成开发任务排期
    • 下午5:20 收到DB主备延迟600M告警
    • 正在紧急coding中,心想备机不影响线上业务..等等看,说不定就好了,...先吃个饭🐶
    • 晚上继续忙...
  • 第2天:
    • 一早来上班,忘了这事..

    • 开始习惯性的查看系统各种指标监控告警邮件

    • 发现邮件数据很奇怪..这些任务完成情况都不对啊,那个定时数据计算任务报告没有出?...

    • 查看db中的数据表,一切都正常

    • 那为何监控告警邮件不对?想起报表系统读的备db..所以主备不一致了!!(终于想起昨天的告警主备延迟还没恢复

    • 为啥会延迟这么多?昨天下午有没有做什么更新删除数据的大事务操作?我似乎没有,别的同学们呢?

继续查看db的监控指标发现,主备延迟了17个小时,也就是说从昨天告警开始到现在的binlog一点都没有恢复。

查找原因

大家都说没有做什么大事务操作。

我们使用云上的MYSQL DB服务,我们使用的db拓扑很简单,如下图:

binlog2.png

只是此时此刻,Master和Slave之间还有大量的binlog没有同步完!

我们找云上的helper帮忙定位问题,定位备机重放binlog的情况。 最终定位到是有一张表还在不停的执行update语句,这个表没有主键

所以延迟17个小时的原因是这个..

这个表是一张统计表,正是我昨天在处理的那张stat_table...

当机立断解决方案:让DBA重建备机

分析原因

主备同步恢复了,我开始分析原因:

  • 昨天在告警之前确实对stat_table新增了一个字段,执行了一两次update操作,

binlog6.png

  • 这么简单的一个操作5s+5s,为何导致主备延迟17小时呢? 操作时没当一回事,50万数据的操作很常见,认为产生不了什么后果。

再描述一下具体场景:

  • 我们的binlog格式设置的是ROW格式(因为也有其他监听的需求)
  • stat_table确实没有设置主键
  • Master上执行一次update stat_table set c=0会产生50万条binlog,两次100万
  • 主备之间的吞吐量不大 那么就是备机回放每条binlog很慢! 为什么回放很慢,下面会具体分析

查看主备binlog

查看binlog需要有root的权限。

首先在Master上查看binlog

  • show binary logs;
    • 查看最后一行就是binlog的最新文件和位置,获取这个文件名Log_name和File_size用于下面的events查看
  • show binlog events in 'Log_name' from File_size limit 100
    • 这个能看到刚刚那个时间点后的binlog事件,但没有显示具体的binlog操作信息
  • mysqlbinlog -uroot -p****** -h****** --read-from-remote-server -vv Log_name --start-position=File_size >binlog.sql
    • 这个能产生binlog的每行的具体执行sql

用vim打开binlog.sql,可以看到binlog的数据大概是这样

 ### UPDATE `db`.`stat_table`
 ### WHERE
 ###   @1=85481 /* INT meta=0 nullable=0 is_null=0 */
 ###   @2=419263 /* INT meta=0 nullable=0 is_null=0 */ 
 ###   @3=1 /* INT meta=0 nullable=0 is_null=0 */
 ### SET
 ###   @1=85481 /* INT meta=0 nullable=0 is_null=0 */
 ###   @2=419263 /* INT meta=0 nullable=0 is_null=0 */
 ###   @3=0 /* INT meta=0 nullable=0 is_null=0 */

binlog7.png

  • stat_table 有a、b、c三列,注意,a、b、c都不是主键。
  • 因为是ROW格式,所以master产生binlog的时候将一条update stat_table set c=0语句拆分成50万,所以binlog里有100万的这个语句

Slave上也可以用同样的方式查看binlog的执行情况, 只不过它的binlog是从Master复制过来的。

备机回放效率分析

假设有主键,在备机上每个update回放执行大概需要0.1ms

这已经假设是很好的性能了,不过这只是一个假设,具体看机器性能。 则执行100万update操作需要10万ms,100s,也就是大概1.5分钟,但这是我们能接受的(用只读备机的地方仅限于报表和一些数据监控)。这也是我们偶尔的有主键表的update或delete操作,备机需要承受的延迟代价。

但是如果没有主键,有普通的索引(a上有普通索引),则UPDATE db.stat_table WHERE @1=85481 @2=419263 @3=0 SET @1=85481 @2=419263 @3=1 这个update语句的开销如何呢?

如下图所示:

binlog11.png

  • stat_table有a、b、c三列,a上有普通索引
  • 虽然stat_table没有主键,但是在DB内部还是会为它建立一个主键(row_id)和对应的索引
  • 普通索引a通过B+树查找匹配的a值,获得一个集合Collection(r1,r2,r3,...),其实r1等都是DB内部创建的主键row_id
  • 假设a索引的每个a值平均有1000行数据,这个就有1000*100万次回主表查找
  • Collection(dr1,r2,r3,...)的元素都要回主表查看,判断是否满足 b 和c列的where条件,如果满足则update,否则不处理 执行一条语句的流程大概是这样,让我们看看不同的情况会发生什么
  • 一共100万个update行,每个1000次回表。和有主键表的情况对比,执行时间放大了1000倍,那么需要1.5*1000分钟!!!因为随机IO的原因,执行时间大于25小时
  • 如果a索引平均每个值有100行数据,则100多分钟,情况已经好了很多
  • 如果这个表什么索引也没有,那就要100万倍,也就是2年

后续和总结

我们的普通索引a平均每个值大概有1000行数据,但是当时没分析之前就重建备机的做法相当明智,毕竟不用再等遥遥无期的主备同步了!

我发现在实际工作中,有这些容易犯错的地方会导致今天的故事:

  • 虽然我们都有很好的DB知识和素养,建表的时候都记得加主键,但我们在做数据计算的时候往往会生成很多表,有时候可能会忘了主键。
  • 另外还有一种类型就是log表,一般任务只会新增不更新,所以可能没有主键问题也不大。但是万一新增功能,更新数据,对主备同步也将造成很大的影响!

此事一出,同学们都将db里的其他无主键表加上了主键..

系统看起来又安全了许多呢~


如果这篇文章对您有所帮助,或有所启发的话,可以点赞收藏或关注:),您的支持是我坚持写作最大的动力。