再議Seconds_Behind_Master，再議主人去收拾善後

再議Seconds_Behind_Master，再議主人去收拾善後

        兩年前就寫過一篇文章解釋Seconds_Behind_Master代表的含義以及它為什麼不準確，今天同事高老師又提了一個有趣的問題：Seconds_Behind_Master到底是怎麼計算的呢？高老師還特地去翻了一下源碼來解釋，我發現我之前的理解還是有出入的，於是自己也動手去翻了一下源碼，下面就來更全面的解釋一下它是怎麼計算的，為什麼不能完全可信。

        我平時讀MySQL源碼比較少，一般來說通過源碼也是查一些基本的問題，對於我來說如果對關鍵代碼位置不熟，比較快捷的方法就是cd到源碼的根目錄，然後grep "Seconds_Behind_Master" . -R -n。結果如下：
 ./sql/rpl_rli.cc:1209:      Seconds_Behind_Master - not critical).
./sql/slave.cc:1345:                      "do not trust column Seconds_Behind_Master of SHOW "
./sql/slave.cc:1874:  field_list.push_back(new Item_return_int("Seconds_Behind_Master", 10,
./sql/slave.cc:1963:      Seconds_Behind_Master: if SQL thread is running and I/O thread is
./sql/slave.cc:3254:    alive and connected, this is going to make Seconds_Behind_Master be 0
./sql/slave.cc:3258:    Seconds_Behind_Master grows. No big deal.
./sql/slave.cc:4666:          We say in Seconds_Behind_Master that we have "caught up". Note that
./sql/slave.cc:4679:          Seconds_Behind_Master would be zero only when master has no


從搜尋結果來看，主要設計到sql/slave.cc以及sql/rpl_rli.cc，而恰好這兩個檔案已經可以解決我們的疑惑了。

首先第一個問題，Seconds_Behind_Master到底是怎麼計算的？

我們先來看手冊上的解釋：

This field is an indication of how “late” the slave is:
When the slave is actively processing updates, this field shows the difference between the current timestamp on the slave and the original timestamp logged on the master for the event currently being processed on the slave.
When no event is currently being processed on the slave, this value is 0.

大意就是如果slave正在處理更新，那麼sbm的計算方式就是：slave當前的時間戳記-正在執行更新的binlog event上附帶的timestamp.如果slave沒有處理更新，那麼sbm=0

那麼這麼解釋對嗎？答案是基本上算對，但是裡面沒解釋一些細節。然後我們通過在slave.cc裡面找到這個真正的計算公式：

1962     /*1963       Seconds_Behind_Master: if SQL thread is running and I/O thread is1964       connected, we can compute it otherwise show NULL (i.e. unknown).1965     */1966     if ((mi->slave_running == MYSQL_SLAVE_RUN_CONNECT) &&1967         mi->rli.slave_running)1968     {1969       long time_diff= ((long)(time(0) - mi->rli.last_master_timestamp)1970                        - mi->clock_diff_with_master);                  此處省略很多注釋1991       protocol->store((longlong)(mi->rli.last_master_timestamp ?1992                                  max(0, time_diff) : 0));1993     }1994     else1995     {1996       protocol->store_null();1997     }

關鍵的代碼如下：

1. long time_diff= ((long)(time(0) - mi->rli.last_master_timestamp)                        - mi->clock_diff_with_master); 2. protocol->store((longlong)(mi->rli.last_master_timestamp ?                                  max(0, time_diff) : 0)); 

到這裡終於看到傳說中的sbm計算方法了，這裡解釋各個變數的含義：
time(0) //從庫當前系統時間戳，Linux系統函數
mi->rli.last_master_timestamp //當前從庫正在執行語句binlog event時間戳記
mi->clock_diff_with_master //主從系統時間戳的差值，slave-master

到這裡我們就知道手冊上其實描述不準確，還少了一部分clock_diff_with_master，因為主庫上記錄binlog event的時間戳記與從庫上計算本地時間戳記time(0)都是調用系統的時間函數，而此時假如說主從時間設定不一致，那麼這個值不就完全沒意義了嗎？因此為了盡量避免這種情況出現，每次在從庫與主庫建立串連的時候都會擷取主從的時間戳記，然後算出一個差值作為一個常量儲存，以後每次算sbm時都會減去這個值。但是有一個問題存在，MySQL只會在建立主從複製串連的時候算這個值，以後都不會再更新，因此假如說主從串連建立好了後去更改主從時間設定，比如NTPD，比如set timestamp=xxx之類的操作，那麼此時看到的sbm的值就會更加不可靠了。

在正常情況下第一句就已經是我們show slave status看到的sbm值了，那麼第二句是為瞭解決什麼問題呢？
1. clock_diff_with_master是主從SELECT UNIX_TIMESTAMP()的差值，很有可能主庫執行的時候是1，從庫執行的時候是2（因為並不能保證主從是同一時刻執行），那麼此時clock_diff_with_master=1, 那麼假設此時time(0)-last_master_timestamp的值等於0，那麼0-1=-1，而-1會給使用者歧義，於是官方在這種情況下會強制把負值變成0
2. 前面說了sbm的值分兩種情況，從庫有SQL線程在處理語句時計算方法剛詳細解釋過，從庫SQL線程沒有處理語句是把這個值設為0，那麼第二句代碼就實現了這個功能，第二句的三元運算式告訴我們，當mi->rli.last_master_timestamp值為0的時候，sbm=0。那麼mi->rli.last_master_timestamp值的更新邏輯是怎樣的呢？

主要有兩個地方：
其一，rpl_rli.cc/Relay_log_info::stmt_done
每次從relay log解析出一條binlog event執行時，last_master_timestamp= event_creation_time;
其二，slave.cc/static Log_event* next_event(Relay_log_info* rli)
進入到下面邏輯的前提條件是relay log已經執行完了，SQL線程在等待relay log有更新

4686         time_t save_timestamp= rli->last_master_timestamp; //先把最後一次處理的binlog event timestamp儲存起來，等將來主庫又推了binlog過來後第一次計算sbm時就可以用了，這也是為什麼有時候start slave後第一次show slave status看到sbm值非常大的一個原因                                   4687         rli->last_master_timestamp= 0;  //把值設為0，那麼前面的三元運算式計算的sbm就是0... 省略部分代碼4779         rli->relay_log.wait_for_update_relay_log(rli->sql_thd); //等待relay log有更新4780         // re-acquire data lock since we released it earlier4781         mysql_mutex_lock(&rli->data_lock);4782         rli->last_master_timestamp= save_timestamp; //重新設定回原值4783         continue;   

然後再來第二個大問題：Seconds_Behind_Master是否可靠？其值為0是否表示主從資料完全一致？
答案必然是否定的。
1. sbm是表示的是relay log中event的延時，而MySQL預設複製是非同步，因此可能從庫relay log執行完，但是主從由於網路以及這種原因主庫上的binlog沒有推送過來，而且我們實際線上也遇到過由於網路原因sbm=0，但主庫的binlog根本就沒推送過來，一般此時通過stop slave/start slave能發現這種假象。所以平常我們去監控主從延時也不會直接用sbm做判斷標準，而是主從建立一張heartbeat表，往主庫插入一條資料來判斷延時情況。
2. 如果主從時間不同步，那麼可能導致sbm延時值不準確

3. 5.6如果開啟了多線程複製，那麼這個值就更加不準了。我這裡也很好奇大家的線上5.6如果開啟了MTS是怎麼來監控主從延時的？

--EOF--