再議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 is
1964 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 else
1995 {
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 earlier
4781 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--
