一个线上问题引发的思考

今天中午线上环境发生了一处报警，报警的内容如下：

PROBLEM P5 Endpoint:10.xx.xxx.xx Metric:mysql.slave.seconds_behind_master Tags:port=3306,service=club,slave_ip=10.xx.xxx.xxx,slave_port=3306 all(#3): 184>100 Note:[[warning]因大事物或从库忙导致延时] Max:3, Current:2 Timestamp:2018-10-18 13:30:00 http://127.0.0.1:8081/portal/template/view/41

通过这个信息提示我们可以看出来，应该是从库发生了一定的延时，可能的原因是主库运行了耗时较长的语句，导致从库一时间跟不上主库。于是我查询了从库的状态：

发现从库的seconds_behind_master确实存在一定的延时，搭建过主从复制的同学们肯定都对seconds_behind_master不陌生，它是描述从库和主库的延时时间的指标，数值越高意味着延迟越大。我首先想到的是应该是主库执行了一些耗时很长的操作，导致了从库的seconds_behind_master值变得特别大，这才出现了告警。

顺着自己的想法，进入到主库的慢日志里面进行查询，看到了如下的结果：

可以看到，这个SQL语句相当长，扫描的行数为2717027行，导致了主库的负载提升，从而表现在从库上为一个很大的Seconds_Behind_Master值。问题算是找到了，这个SBM的值也随着时间慢慢的降了下来，但是在这个过程中，产生了一个新的疑问，这个Seconds_behind_master值对我们来讲，到底有多大的意义，它的值到底代表着什么。

从上面的问题分析，首先可以确定的是，这个SBM的值肯定不是准确是，它只能作为一种参考，也就是说当SBM为0的时候，并不真正意味着从库已经追上主库了。在发生故障之前，SBM一直都是0，在某一个时间点之后突然就变得非常高。这是由于在主库上执行了一个非常大的event，在这个event在主库上没执行完毕的时候，从库的SBM会显示为0，而当主库执行完毕传到从库上开始执行的时候，就会显示SBM非常巨大了。

MySQL官方对这个参数的值是这么定义的：

Seconds_Behind_Master:

The number of seconds that the slave SQL thread is behind processing the master binary log

也就是说，它是SQL thread在执行IO thread dump下来的relay log的时间差。大家都知道relay log中event记录的时间戳是主库上的时间戳，而SQL thread的时间戳是从库上的，也就是说，如果主库和从库的时间是一致的，那么这个SBM代表的确实是从库延后主库的一个时间差。但是如果主库和从库的时间不是一致的，那么这个SBM的意义就基本不存在了。

看到这里，我又产生了一个新的疑问，MySQL的同步是异步完成的，其中IO thread负责接收从主库dump的binlog到从库上生成relay log，然后SQL thead负责解析relay log后在从库上进行重放来完成同步。这个2步是完全异步的，单独停止其中一个，并不会影响另一个的正行工作。当这两个thread都正常工作的时候，show slave status会显示双Yes状态，表示同步正常。那么今天发生的这种情况，明显的是主库已经发生了变化，为什么从库没有第一时间发现主库的变化，而是直接从SBM值为0跳到了SBM值为206的情况呢？？？

明天有空研究一下这个问题，回头再给出答案。