Seconds_behind_master反复横跳?
今天在线上遇到了一个mysql的问题,这里记录一下。
场景:
1、监控报警某个业务的从库有延迟
2、show slave status查看seconds_behind_master值反复在0、500、0、500、0、500之间跳动。
seconds_behind_master下面简称SBM。
这种问题,更多的是先从官方文档上去查看一些蛛丝马迹。
SBM的具体意思,想必大家都知道,它是指主从复制的SQL线程落后于主库binlog的时间(也就是从库的relay-log中的时间)。
在官方文档上,找到一句话:
链接:https://dev.mysql.com/doc/refman/8.0/en/replication-administration-status.html
这不就是我们遇到的情况嘛。
这段话翻译过来就是:在一些场景下,SBM的瞬时值并不能反映准确的情况。当复制的SQL线程追赶上IO线程的时候,这个值显示为0;当复制IO在等待新的事件的时候,SBM值显示为一个较大的值,直到复制线程执行完了这个新的event。而这种情况在某个事件具有旧的时间戳的时候,经常容易发生。在这种情况下,你就会看到SBM值在0和一个较大的值之间反复横跳。
有了上述的理论基础,我们来看我们的真实情况:
先来看主库上真实的binlog位置:
show master statusG *************************** 1. row *************************** File: mysql-bin.004718 Position: 841616814 Binlog_Do_DB: Binlog_Ignore_DB: Executed_Gtid_Set: 1 row in set (0.00 sec)
可以看到,主库的binlog是4718这个号。
再来看下从库复制的主库位置:
show slave statusG *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.xx.xx.xx Master_User: replica Master_Port: 3306 Connect_Retry: 60 Master_Log_File: mysql-bin.004717 Read_Master_Log_Pos: 353151416 Relay_Log_File: relay-bin.002983 Relay_Log_Pos: 353151460 Relay_Master_Log_File: mysql-bin.004717 Slave_IO_Running: Yes Slave_SQL_Running: Yes Exec_Master_Log_Pos: 353151301 Relay_Log_Space: 353151781
可以看到,从库复制的主库binlog编号是4717.
当前这种情况,就是从库的IO线程比较慢,复制的主库的binlog不是最新的binlog,而是上一个binlog,自然而然就带有了这个老旧的时间戳。所以从库的IO线程在排队等待某个事务中的新事件的时候,就使得SBM值变为一个比较大的数字,(500s)。然后等到复制SQL线程追上IO线程的时候,这个SBM的值又变成了0.
以上猜测,在实际分析binlog的时候,也被证明了。当前的从库的relay log中,确实有很多超级大的insert操作,而且从库的relay log中的时间戳,记录的时间基本都是当前从库时间9分钟以前,恰好500s左右。
关于SBM值,还有几点需要说明:
1、在从库忙的时候,SBM记录的是从库时间戳和来自主库的binlog中的时间戳之间的差异
2、当从库空闲时,如果I/O和SQL线程状态双Yes,SBM=0,如果有任意一个线程状态不为Yes,SBM=NULL
3、假设主从服务器时间戳不一致,如果从库复制线程启动之后,没有做过任何时间变更,那么SBM的值也可以正常计算,但是如果修改了从库或者主库的时间,则可能导致时钟偏移,从而导致这个计算值不可靠
4、如果从库上有人为写入新数据,则可能导致SBM的值随机波动。
5、在网络条件较差的环境下,如果IO 线程延时严重,即使SBM的值为0,也不能说明主从之间没有延迟。
更多内容,请参考之前的文章:
MySQL Second_Behind_Master值官方解读
最后,抛一个问题吧,如果IO Thread很慢,有延时,那应该怎么处理呢?优化网络环境?端口拆分降低主库写入?
你还有更好的方法吗?欢迎赐教。