Seconds_behind_master反復橫跳？

   今天在線(xiàn)上遇到了一個(gè)MySQL的問(wèn)題，這里記錄一下。

場(chǎng)景：

1、監控報警某個(gè)業(yè)務(wù)的從庫有延遲

2、show slave status查看seconds_behind_master值反復在0、500、0、500、0、500之間跳動(dòng)。

seconds_behind_master下面簡(jiǎn)稱(chēng)SBM。

    這種問(wèn)題，更多的是先從官方文檔上去查看一些蛛絲馬跡。

    SBM的具體意思，想必大家都知道，它是指主從復制的SQL線(xiàn)程落后于主庫binlog的時(shí)間（也就是從庫的relay-log中的時(shí)間）。

在官方文檔上，找到一句話(huà)：

It is also possible that transient values for Seconds_Behind_Source may not reflect the situation accurately. When the replication SQL (applier) thread has caught up on I/O, Seconds_Behind_Source displays 0; but when the replication I/O (receiver) thread is still queuing up a new event, Seconds_Behind_Source may show a large value until the replication applier thread finishes executing the new event. This is especially likely when the events have old timestamps; in such cases, if you execute SHOW REPLICA 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.

鏈接：https://dev.mysql.com/doc/refman/8.0/en/replication-administration-status.html

    這不就是我們遇到的情況嘛。

    這段話(huà)翻譯過(guò)來(lái)就是：在一些場(chǎng)景下，SBM的瞬時(shí)值并不能反映準確的情況。當復制的SQL線(xiàn)程追趕上IO線(xiàn)程的時(shí)候，這個(gè)值顯示為0；當復制IO在等待新的事件的時(shí)候，SBM值顯示為一個(gè)較大的值，直到復制線(xiàn)程執行完了這個(gè)新的event。而這種情況在某個(gè)事件具有舊的時(shí)間戳的時(shí)候，經(jīng)常容易發(fā)生。在這種情況下，你就會(huì )看到SBM值在0和一個(gè)較大的值之間反復橫跳。

    有了上述的理論基礎，我們來(lái)看我們的真實(shí)情況：

先來(lái)看主庫上真實(shí)的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這個(gè)號。

再來(lái)看下從庫復制的主庫位置：

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線(xiàn)程比較慢，復制的主庫的binlog不是最新的binlog，而是上一個(gè)binlog，自然而然就帶有了這個(gè)老舊的時(shí)間戳。所以從庫的IO線(xiàn)程在排隊等待某個(gè)事務(wù)中的新事件的時(shí)候，就使得SBM值變?yōu)橐粋€(gè)比較大的數字，（500s）。然后等到復制SQL線(xiàn)程追上IO線(xiàn)程的時(shí)候，這個(gè)SBM的值又變成了0.

以上猜測，在實(shí)際分析binlog的時(shí)候，也被證明了。當前的從庫的relay log中，確實(shí)有很多超級大的insert操作，而且從庫的relay log中的時(shí)間戳，記錄的時(shí)間基本都是當前從庫時(shí)間9分鐘以前，恰好500s左右。

    關(guān)于SBM值，還有幾點(diǎn)需要說(shuō)明：

1、在從庫忙的時(shí)候，SBM記錄的是從庫時(shí)間戳和來(lái)自主庫的binlog中的時(shí)間戳之間的差異

2、當從庫空閑時(shí)，如果I/O和SQL線(xiàn)程狀態(tài)雙Yes，SBM=0，如果有任意一個(gè)線(xiàn)程狀態(tài)不為Yes，SBM=NULL

3、假設主從服務(wù)器時(shí)間戳不一致，如果從庫復制線(xiàn)程啟動(dòng)之后，沒(méi)有做過(guò)任何時(shí)間變更，那么SBM的值也可以正常計算，但是如果修改了從庫或者主庫的時(shí)間，則可能導致時(shí)鐘偏移，從而導致這個(gè)計算值不可靠 

4、如果從庫上有人為寫(xiě)入新數據，則可能導致SBM的值隨機波動(dòng)。

5、在網(wǎng)絡(luò )條件較差的環(huán)境下，如果IO 線(xiàn)程延時(shí)嚴重，即使SBM的值為0，也不能說(shuō)明主從之間沒(méi)有延遲。