MySQL alter table时执行innobackupex全备再谈Seconds_Behind_Master

1.场景描述

早上7：25 接到Report中心同学告警，昨天业务报表数据没有完整跑出来，缺少500位业务员的数据，并且很快定位到，缺少的是huabei_order库上的数据。Report中心的数据是BI每天5:15从huabei_order库的从库上抽取。查看监控告警，从库实例确实在4:50 –6:00 有延迟，但已恢复。报表数据不完整，直接原因就是主从延迟。

7:50 确认主从延迟已恢复，请求BI重新抽取数据，重新生成报表。

8：20 报表数据验证无误。

问题还没结束：

忽略监控告警的不及时、不完整。

还需要回答的问题是为什么在业务低峰期会出现延迟？是什么操作造成的？【问题1】

监控界面主从延迟指标

看到这样的走势图，又一个需要思考的问题:为什么延迟会瞬间飙升到24440s以上（实际可能已达25K以上），延迟不应该是逐渐累积的吗？【问题2】

确实是业务低峰期，和研发、产品、业务确认，23:30 之后没有大的操作、大的流量，也没有特别的活动、促销。从数据库Server业务压力上考虑，确实没有特殊的操作。

忽然想到，备份，完整备份。我们的灾备，数据库的完整备份实在从库上做的，cron 设置在每天的00:05 , 一般执行2个小时， 并且是周二、周五执行，当天正好是周二。

虽然自己也不太相信这个就是真正的原因，但毕竟是一个可考虑的因素。查看完整备份的log。

2.全量备份

失败

报错信息如下:

210831 04:49:46 >> log scanned up to (1168680308582)
210831 04:49:47 >> log scanned up to (1168680308668)
210831 04:49:48 >> log scanned up to (1168680308770)
210831 04:49:49 >> log scanned up to (1168680308856)
210831 04:49:50 >> log scanned up to (1168680308942)
210831 04:49:51 >> log scanned up to (1168680309028)
210831 04:49:52 >> log scanned up to (1168680309114)
InnoDB: Last flushed lsn: 1168515708469 load_index lsn 1168680309114 InnoDB: An optimized (without redo logging) DDLoperation has been performed. All modified pages may not have been flushed to the disk yet.
PXB will not be able take a consistent backup. Retry the backup operation
mysql: [Warning] Using a password on the command line interface can be insecure.

 失败了，并且时间都很吻合，04:49 完整备份失败，04:49 主从延迟瞬间飙升。

 查看完整备份历史，过去备份耗时在2个小时左右，而本次备份执行了4个小时50分钟，还失败了。

（说明:从完整备份打印的log来看，打印FLUSH TABLES WITH READ LOCK时，完整备份就快结束了，所以，在此图上，通过FLUSH TABLES WITH READ LOCK的时间代表完整备份结束的时间）

到此时，相信很多同学，已经准备把锅甩给完整备份了。

需要思考的问题 :DDL操作和xtrabackup是怎么相互影响的？为什么全量备份失败后，延迟问题才会马上被监控到（Seconds_Behind_Master才显示异常）？【问题3】

3.继续分析原因，寻找DDL

每个问题都不简单。

我们先看问题3.DDL操作和xtrabackup是怎么相互影响的？为什么全量备份失败后，延迟问题才会马上被监控到（Seconds_Behind_Master才显示异常）？【问题3】

回答这个问题，需要先找到具体的DDL操作。

但是备份期间没有执行过DDL操作。上次一DDL操作 要追溯到前一天19:50。迷雾重重、元凶隐隐。

想到MySQL DDL操作，一般执行时间相对较长，slow log 中或许有蛛丝马迹。

ELK–MySQL日志系统走起。

还是找到了一条大鱼，alter table ,添加字段。时间点吻合（04:49）,执行时间超长25438秒（并且和Seconds_Behind_Master飙升后的值很接近 ）。

从库DDL执行log

 25438秒 ≈ 7 小时

 从库所有的操作都来自主库，接下来，我们看下主库啥时候执行DDL的。

主库DDL执行情况

主库执行了 5089 秒，结束于 前一天的21：18。向前推 5089 秒，也就是 19:50前后。

为什么执行时间会这么长呢？这张表确实是大表、宽表–1.6 亿 数据量、130G大小，其信息如下:

所以，到现在，才算把主从延迟的问题定位到—–DDL 和 innobackupex。两者相互影响、相互拖累，才导致这个时间段内的延迟产生。这也算问题1的答案吧。

4.Seconds_Behind_Master 问题解答

此处我们尝试问答第二个问题:为什么延迟,会瞬间飙升到24440S以上，延迟不应该是逐渐累积的吗？【问题2】

我么先看下主从复制指标:Seconds_Behind_Master 的官方描述

Seconds_Behind_Master: The number of seconds that the replication SQL thread is behind processing the source”s binary log. A high number (or an increasing one) can indicate that the replica is unable to handle events from the source in a timely fashion.

A value of 0 for Seconds_Behind_Master can usually be interpreted as meaning that the replica has caught up with the source, but there are some cases where this is not strictly true. For example, this can occur if the network connection between source and replica is broken but the replication I/O thread has not yet noticed this—that is, slave_net_timeout has not yet elapsed.

It is also possible that transient values for Seconds_Behind_Master may not reflect the situation accurately. When the replication SQL thread has caught up on I/O, Seconds_Behind_Master displays 0; but when the replication I/O thread is still queuing up a new event, Seconds_Behind_Master may show a large value until the SQL thread finishes executing the new event. This is especially likely when the events have old timestamps; in such cases, if you execute SHOW SLAVE STATUS several times in a relatively short period, you may see this value change back and forth repeatedly between 0 and a relatively large value.

Check the Seconds_Behind_Master column in the output from SHOW REPLICA | SLAVE STATUS. 

When the replication SQL thread executes an event read from the source, it modifies its own time to the event timestamp. (This is why TIMESTAMP is well replicated.) In the Time column in the output of SHOW PROCESSLIST, the number of seconds displayed for the replication SQL thread is the number of seconds between the timestamp of the last replicated event and the real time of the replica machine. You can use this to determine the date of the last replicated event. Note that if your replica has been disconnected from the source for one hour, and then reconnects, you may immediately see large Time values such as 3600 for the replication SQL thread in SHOW PROCESSLIST. This is because the replica is executing statements that are one hour old.

通过以上的描述 和 本 Case 中 Seconds_Behind_Master 的数字变化：

Seconds_Behind_Master 似乎应该为:SQL thread 重做主节点同步过来的binlog even, 执行提交后，比较从节点执行even的时间和主节点binlog event 中的时间所得到时间差。

再回答这个问题， Seconds_Behind_Master瞬间飙升到24440S 以上【因为我们的telegraf 抓取是20S一次，并且从监控库图上可看到，有一个快速下降趋势，所以，真正的最大值应该为25K以上，很可能会比慢查询的25438 还稍微大些】，这个值是怎么来的？应该就是从库DDL提交的时刻【04：49】减去主库DDL提交的时刻【前一天的21:18】的差值。 —这也算问题2的答案吧。

 所以，Seconds_Behind_Master = 0 时，主从延迟可能已经很厉害了，除了官网提到的网络问题，还有就是从库正则执行同步过来的大DDL（尚未提交）。例如在本例的00:00—04:00 其实已经存在延迟了。

5.innobackupex知识补充

关于问题 3中 为什么全量备份失败后，延迟问题才会马上被监控到（Seconds_Behind_Master才显示异常）？ 目前来看，尚未分析到直接因果关系，应该是概率事件。

innobackupex备份流程图如下：

经过验证测试，innobackupex备份开始时，并不是先看当前数据库是否有DDL操作，而是其中的某个线程在备份这张表时（或 scan lsn）才判断是否有DDL，有则推出报错。验证方法，在一张大表上执行DDL（保证DDL时间足够长），在DDL运行期间，开始备份，我们我看到这个很多表在执行copy备份，是运行了一段时间后，才报错的。

此外， innobackupex备份过程中，执行DDL，都会导致备份失败，与表大小无关，即使这张表只有一笔数据。

补充说明：

MySQL版本为5.7.22

innobackupex的版本为 innobackupex version 2.4.9 Linux (x86_64) (revision id: a467167cdd4)

6.参考文献

1.mysqldump与innobackupex备份过程知多少（完结篇）

https://blog.csdn.net/joy0921/article/details/80130860

2.MySQL中的seconds_behind_master的理解

https://www.cnblogs.com/drizzle-xu/p/9713350.html?ivk_sa=1024320u

 3.How do I know how late a replica is compared to the source? 

https://dev.mysql.com/doc/refman/8.0/en/faqs-replication.html