MySQL 複製延遲 Seconds_Behind_Master 究竟是如何計算的

作者：羅小波

參考連結

https://dev.mysql.com/doc/refman/5.7/en/show-slave-status.html 

https://wemp.app/posts/33881a28-ba27-4908-994e-29440455d5be https://blog.csdn.net/innobase/article/details/51302138

目錄

• “口口相傳” 的計算方法
• 探尋 “正確” 的計算方法
• 驗證

  我們想確認什麼

  提前確認一些資訊

  執行驗證

• 總結

背景說明

在使用主從複製的拓撲中，監控複製延遲時間是必不可少的功課，如果應用場景對複製延遲並不敏感，那麼，大多數時候透過採集 SHOW SLAVE STATUS 陳述句輸出資訊中的 Seconds_Behind_Master 欄位值來監控複製延遲就已經足夠了，相信有MySQL使用經驗的人對透過這種方法來檢視複製延遲並不陌生，我們都知道 Seconds_Behind_Master 的值在某些場景下並不是那麼可靠，也或多或少都知道一些 Seconds_Behind_Master 欄位值計算方法。但這些計算方法真的正確麼？

本著鑽研的精神，今天我就較真一回，搜羅一些關於計算方法的傳說，併進行一些簡單的驗證，整理出來，洋洋灑灑寫了一大篇，在這裡分享給大家

一、”口口相傳” 的計算方法

►方法一：從庫 I/O 執行緒讀取的主庫 binlog event 時間戳與 SQL 執行緒正在執行的 binlog event 的時間戳之間的時間差，單位為秒

該方法其實就是在計算兩個執行緒處理日誌的時間差，這也是目前最為 “流行” 的一種說法。基於這個演演算法，如果主從之間的網路存在很大延遲的時候，主庫中就可能存在著大量的binlog還沒來得及傳送給從庫，那麼這個時候其實使用該方法計算出來的延遲時間，跟主從之間資料真正的延遲就沒有太大關係了

▶方法二：從庫的系統（主機）時間與 I/O 執行緒讀取的主庫 binlog event 的時間差之間的時間差，單位為秒

這種說法沒那麼 “流行” ，基於這個演演算法，如果從庫的作業系統時間被更改了，或者主庫的作業系統時間被修改了，即主從庫的主機時間差本身就比較大的時候，那麼計算出來的結果也毫無參考意義

▶ 結論，看起來這兩種演演算法都不太靠譜，正確的演演算法真的是這樣的嗎？為了一探究竟，我們需要找到可靠的資訊源進行確認。

那麼從哪裡可以獲得可靠的資訊源呢？

二、探尋 “正確” 的計算方法

▶ 資訊源一：MySQL 官方手冊

• 為了不佔篇幅、也為了避免本人英文理解錯誤，下麵直接貼出官方手冊中關於 Seconds_Behind_Master 欄位值計算描述的原文

大概的含義：

* 當從庫正在不斷地處理更新時（持續不斷有event被SQL執行緒或者I/O執行緒處理時），此欄位顯示從庫主機當前時間戳和來自主庫（原始）的二進位制日誌中記錄的時間戳之間的差異 

* 當從庫沒有任何需要處理的更新時，如果I/O和SQL執行緒狀態都為Yes，則此欄位顯示為0，如果有任意一個執行緒狀態不為Yes，則此欄位顯示為NULL 

* 實際上，這個欄位是度量從庫SQL執行緒和I/O執行緒之間的時間差，單位為秒，如果主備之間的網路非常快，那麼從庫的I/O執行緒讀取的主庫binlog會與主庫中最新的binlog非常接近，所以這樣計算得來得值就可以作為主備之間的資料延遲時間，但是如果主備之間的網路非常慢，可能導致從庫SQL執行緒正在重放的主庫binlog 非常接近從庫I/O執行緒讀取的主庫binlog，而I/O執行緒因為網路慢的原因可能讀取的主庫binlog遠遠落後於主庫最新的binlog，此時，這麼計算得來的值是不可靠的，儘管這個時候有可能該欄位顯示為0，但實際上可能從庫已經落後於主庫非常多了。所以，對於網路比較慢的情況，該值並不可靠

* 如果主庫與從庫的server自身的時間不一致，那麼，只要從庫複製執行緒啟動之後，沒有做過任何時間變更，那麼這個欄位的值也可以正常計算，但是如果修改了server的時間，則可能導致時鐘偏移，從而導致這個計算值不可靠 

* 如果從庫的SQL執行緒沒執行、SQL執行緒正在執行且已經消費完了所有的relay log且I/O執行緒沒有執行，則該欄位顯示為NULL（如果I/O執行緒已經停止，但還存在著relay log未重放完成時，仍然會顯示出複製延遲時間，直到所有relay log被重放完成之後，顯示為NULL），如果SQL執行緒和I/O執行緒都執行著，但是處於空閑狀態（SQL執行緒已經重放完了I/O執行緒產生的

relay log），則該欄位顯示為0 

* 該欄位的值是基於儲存在主庫binlog event中的時間戳，保留這個時間戳並透過複製架構同步到從庫進行計算得來，那就意味著正常的複製情況下（排除人為在從庫寫入資料的情況）主庫與從庫上的binlog event的時間戳都來自主庫，在目前的計算該欄位值的演演算法中有一個問題，在單執行緒複製場景下，即如果從庫上透過客戶端連線進入並直接更新資料，這可能導致該欄位的值隨機波動，因為有時候event來源於主庫，有時候來源於從庫直接更新產生的event，而這個欄位的值會受到直接更新產生的event的影響。但如果是多執行緒複製，則此值是基於Exec_Master_Log_Pos點的event時間戳來計算的，因此可能不會反映從庫最近提交的事務的位置

▶ 資訊源二：原始碼

以下是原始碼中關於延遲時間計算方法的註釋說明 

# 位於rpl_mi.h中定義clock_diff_with_master附近（翻閱了5.6.34和5.7.22 兩個版本，對於複製延遲的計算公式兩者一致）
# 從原始碼註釋上來看，複製延遲的計算公式為 clock_of_slave - last_timestamp_executed_by_SQL_thread - clock_diff_with_master
# 該公式的含義為：從庫的當前系統（主機）時間 - 從庫 SQL 執行緒正在執行的event的時間戳 - 主從庫的系統（主機）之間的時間差
/*
     The difference in seconds between the clock of the master and the clock of
     the slave (second - first). It must be signed as it may be <0 or >0.
     clock_diff_with_master is computed when the I/O thread starts; for this the
     I/O thread does a SELECT UNIX_TIMESTAMP() on the master.
     "how late the slave is compared to the master" is computed like this:
     clock_of_slave - last_timestamp_executed_by_SQL_thread - clock_diff_with_master

  */
# clock_diff_with_master 值為主從伺服器的主機時間差，該值只在I/O執行緒啟動時計算一次，後續每次計算Seconds_Behind_Master欄位值時，是直接復用這個計算結果，每次重啟I/O執行緒時該值會重新計算
  long clock_diff_with_master;  

# master_row[0] 為從庫在主庫上執行SELECT UNIX_TIMESTAMP()的操作，clock_diff_with_master為主從庫主機的時間差計算結果
  mi->clock_diff_with_master=
      (long) (time((time_t*) 0) - strtoul(master_row[0], 0, 10));

# 從rpl_slave.cc 檔案中啟動 I/O 執行緒時可以看出：
      start_slave_thread-> # 啟動start slave
            handle_slave_io-> # 啟動start io thread
                get_master_version_and_clock # 獲取當前slave和主機之間的時間差(clock_diff_with_master)

以下是原始碼中關於Seconds_Behind_Master 計算結果的一些判定值

/*
   The pseudo code to compute Seconds_Behind_Master:  # 闡明這是一段註釋關於如何計算Seconds_Behind_Master的偽程式碼
   if (SQL thread is running)  # 如果SQL執行緒正在執行，則進入這個if判斷內，假設這裡標記為if one
   {
     if (SQL thread processed all the available relay log)  # 如果SQL執行緒應用完成了所有可用的relay log，則進入這個if判斷內，假設這裡標記為if two
     {
       if (IO thread is running)  # 如果I/O執行緒正在執行，則進入這個if判斷內，假設這裡標記為if three
          print 0;  # 如果if one/two/three三個條件都為真，則延遲值判定為0
       else
          print NULL;  # 如果if one/two為真，if three為假，則延遲值判定為NULL
     }
      else
        compute Seconds_Behind_Master;  # 如果if one為真，if two為假，則執行公式計算延遲值
    }
    else
     print NULL;  # 如果if one為假，則延遲值判定為NULL
*/

if (mi->rli->slave_running)
{
  /*
     Check if SQL thread is at the end of relay log
     Checking should be done using two conditions
     condition1: compare the log positions and
     condition2: compare the file names (to handle rotation case)
  */
  if ((mi->get_master_log_pos() == mi->rli->get_group_master_log_pos()) &&
      (!strcmp(mi->get_master_log_name(), mi->rli->get_group_master_log_name())))
  {
    if (mi->slave_running == MYSQL_SLAVE_RUN_CONNECT)
      protocol->store(0LL);
    else
      protocol->store_null();
  }
  else
  {
    long time_diff= ((long)(time(0) - mi->rli->last_master_timestamp)
                     - mi->clock_diff_with_master);
    /*
      Apparently on some systems time_diff can be <0. Here are possible
      reasons related to MySQL:
      - the master is itself a slave of another master whose time is ahead.
      - somebody used an explicit SET TIMESTAMP on the master.
      Possible reason related to granularity-to-second of time functions
      (nothing to do with MySQL), which can explain a value of -1:
      assume the master's and slave's time are perfectly synchronized, and
      that at slave's connection time, when the master's timestamp is read,
      it is at the very end of second 1, and (a very short time later) when
      the slave's timestamp is read it is at the very beginning of second
      2. Then the recorded value for master is 1 and the recorded value for
      slave is 2. At SHOW SLAVE STATUS time, assume that the difference
      between timestamp of slave and rli->last_master_timestamp is 0
      (i.e. they are in the same second), then we get 0-(2-1)=-1 as a result.
      This confuses users, so we don't go below 0: hence the max(). 

      last_master_timestamp == 0 (an "impossible" timestamp 1970) is a
      special marker to say "consider we have caught up".
    */
    protocol->store((longlong)(mi->rli->last_master_timestamp ?
                                 max(0L, time_diff) : 0));  # time_diff這裡其實就是最終計算的Seconds_Behind_Master 值，如果為負數，則直接歸零
  }
}

三、驗證

1、我們想確認什麼

正所謂 “盡信書不如無書” ，我們不能 “它說是這樣我們就信了” ，所以，我們這裡簡單對官方手冊和原始碼中提及的計算公式、場景進行簡單的驗證，看看實際的表現如何

• 根據上文原始碼中的註釋，我們找到了計算複製延遲的 “正確” 方法（公式）為：

  * clock_of_slave – last_timestamp_executed_by_SQL_thread – clock_diff_with_master，該公式含義為 “從庫的當前系統（主機）時間 – 從庫 SQL 執行緒正在執行的event的時間戳 – 主從庫的系統（主機）之間的時間差”

  * 計算公式中的clock_diff_with_master值，也就是主從庫的主機時差只在I/O執行緒啟動的時候計算一次（後續會復用該計算結果來計算複製延遲，直到下次重啟I/O執行緒時才會重新計算）

• 根據上文官方手冊中的描述，主從庫系統時間不一致也支援正確計算複製延遲：

  * 如果主從庫的系統時間不一致，那麼如果在複製執行緒（I/O執行緒）啟動之後，沒有對主庫或者從庫的系統時間再次進行修改，那麼根據公式是可以正確計算複製延遲時間的，除非在複製啟動之後再次修改了主從庫的系統時間，就會導致複製延遲時間不可靠（因為計算公式中的clock_diff_with_master 只在I/O執行緒啟動時才會進行計算，後續計算複製延遲時會復用該計算結果）

• 根據上文原始碼中的描述，當Seconds_Behind_Master計算結果為負數的時候，直接歸零

2、提前確認一些資訊

首先：我們需要確認當I/O執行緒啟動之後，會在主庫上執行一些什麼動作？

然後：我們需要確認直接修改主機時間之後，在資料庫中執行一些時間函式是傳回的時間資訊是否會跟著改變，寫入到二進位制日誌中的時間資訊是否會跟著改變？

我們先來看第一個問題，當I/O執行緒啟動之後，會在主庫上執行一些什麼動作？

先在主庫開啟general_log

root@localhost : (none) 10:09:47> set global general_log=1; 
Query OK, 0 rows affected (0.01 sec)

從庫啟動 I/O 執行緒 

root@localhost : (none) 10:16:33> start slave io_thread; 
Query OK, 0 rows affected (0.00 sec)

檢視主庫general_log中記錄的內容

2019-04-18T10:16:36.414222+08:00 8 Connect qbench@10.10.30.162 on using TCP/IP
2019-04-18T10:16:36.414632+08:00 8 Query SELECT UNIX_TIMESTAMP()  # 在主庫查詢系統時間陳述句，這裡可以證實I/O執行緒啟動的時候會獲取主庫的系統時間，當從庫拿到主庫的系統時間之後，就可以計算主從庫的系統時間之差
2019-04-18T10:16:36.415401+08:00 8 Query SELECT @@GLOBAL.SERVER_ID  # 查詢主庫的SERVER_ID
2019-04-18T10:16:36.415638+08:00 8 Query SET @master_heartbeat_period= 5000000000  # 對dump執行緒在會話級別設定心跳間隔時間
2019-04-18T10:16:36.415814+08:00 8 Query SET @master_binlog_checksum= @@global.binlog_checksum
2019-04-18T10:16:36.416129+08:00 8 Query SELECT @master_binlog_checksum
2019-04-18T10:16:36.416335+08:00 8 Query SELECT @@GLOBAL.GTID_MODE  # 查詢主庫的GTID樣式值
2019-04-18T10:16:36.416527+08:00 8 Query SELECT @@GLOBAL.SERVER_UUID  # 查詢主庫的UUID
2019-04-18T10:16:36.416693+08:00 8 Query SET @slave_uuid= '2d623f55-2111-11e8-9cc3-0025905b06da' # 會話級別設定從庫自己的UUID
2019-04-18T10:16:36.417224+08:00 8 Binlog Dump GTID Log: '' Pos: 4 GTIDs: '06188301-b333-11e8-bdfe-0025905b06da:1-270852,
2d623f55-2111-11e8-9cc3-0025905b06da:1,
f3372787-0719-11e8-af1f-0025905b06da:1-21'

現在，我們來看第二個問題。修改主機時間之後（資料庫行程不重啟），在資料庫中執行一些時間函式時傳回的時間資訊是否會跟著改變，寫入到二進位制日誌中的時間資訊是否會跟著改變

在主庫的主機中修改時間 

# 修改之前先查詢一下主機和資料庫中的時間，都為2019-04-19 16:14附近
[root@localhost ~]# date
2019年 04月 19日 星期五 16:14:19 CST

# 修改之前先檢視資料庫中的時間
mysql > select now(),unix_timestamp(),from_unixtime(unix_timestamp());
+---------------------+------------------+---------------------------------+
| now() | unix_timestamp() | from_unixtime(unix_timestamp()) |
+---------------------+------------------+---------------------------------+
| 2019-04-19 16:14:20 | 1555661660 | 2019-04-19 16:14:20 |
+---------------------+------------------+---------------------------------+

# 修改主機時間為2020-04-19 17:15:00
[root@localhost ~]# date -s '2020-04-19 17:15:00'
2020年 04月 19日 星期日 17:15:00 CST

# 發現在資料庫中使用unix_timestamp()函式查詢到的時間跟隨著主機時間變化了，也變為了2020-04-19 
mysql > select now(),unix_timestamp(),from_unixtime(unix_timestamp());
+---------------------+------------------+---------------------------------+
| now() | unix_timestamp() | from_unixtime(unix_timestamp()) |
+---------------------+------------------+---------------------------------+
| 2020-04-19 17:15:03 | 1587287703 | 2020-04-19 17:15:03 |
+---------------------+------------------+---------------------------------+

# 插入一點測試資料，解析binlog，發現binlog中的時間戳也跟著發生了變化，也變為了2020-04-19 ，這裡就可以證實主機時間的修改將直接影響資料庫中時間函式獲取的時間以及binlog的時間戳
......
# at 468
#190419 16:14:29 server id 3306154 end_log_pos 499 CRC32 0x80c44c50 Xid = 74
COMMIT/*!*/;
# at 499
#200419 17:15:08 server id 3306154 end_log_pos 564 CRC32 0xc2794ccb GTID last_committed=1 sequence_number=2 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'c413c893-56b0-11e9-a705-000c29c10fa5:35'/*!*/;
......

3、執行驗證

• • 驗證場景

1、在主庫持續每秒有資料寫入的情況下（指令碼持續的每隔一秒插入10行資料）驗證主庫和從庫各自向前和向後修改主機時間、主從庫同時向前和向後修改主機時間時，從庫的複製延遲時間如何變化（指令碼持續每秒鐘獲取一次Seconds_Behind_Master欄位值）

2、sysbench 加壓到從庫存在複製延遲的情況下，突然停止主庫壓力或突然停止從庫 I/O執行緒時，從庫複製延遲時間如何變化

• 驗證結果 

四、總結

根據以上可靠的資訊來源以及測試驗證過程可以簡單得出如下一些結論

1. 對於主從庫主機時間不一致的情況，在I/O執行緒第一次啟動時，會計算主從之間的主機時間差，在後續計算複製延遲時，會把這個時間差減掉，這樣就可以保證正確獲取到複製延遲時間，但是該時間差只在I/O執行緒啟動時才會進行計算，所以，當I/O執行緒啟動之後修改了主從庫的主機時間，則根據計算公式，會導致複製延遲時間不可靠，但是當I/O執行緒重啟之後就可以恢復（因為I/O執行緒重啟時，主從之間的時間差重新計算了）
2. 在計算複製延遲時（執行 SHOW SLAVE STATUS陳述句時會進行計算），對Seconds_Behind_Master計算結果做一些判定（上文原始碼介紹部分的偽程式碼註釋裡有講解過，這裡再囉嗦一下）：

   * 如果 I/O 和 SQL執行緒同時為 Yes，且SQL執行緒沒有做任何事情（沒有需要被執行的event），此時直接判定複製延遲結果為0，不會走公式計算延遲時間，否則會走公式計算延遲時間（所以，在該前置條件下不會出現當主庫沒有寫任何binlog event時，從庫延遲不斷加大的情況）

   * 如果 SQL執行緒為Yes，且還存在著 I/O 執行緒已經讀取的relay log未應用完成的，則會走公式計算延遲時間，而不管 I/O執行緒是否正在執行，但當SQL執行緒重放完成了所有relay log時，如果 I/O執行緒不為Yes，直接判定複製延遲結果為NULL

   * 任何時候，如果SQL執行緒不為Yes，直接判定複製延遲結果為NULL。當計算出的複製延遲為負數時，直接歸零

補充說明：

1、當SQL執行緒重放大事務時，SQL執行緒的時間戳更新相當於被暫停了（因為一個大事務的event在重放時需要很長時間才能完成，雖然這個大事務也可能會有很多event，但是這些event的時間戳可能全都相同），此時，根據計算公式可以得出，無論主庫是否有新的資料寫入，從庫複製延遲仍然會持續增大（也就是說此時的複製延遲值是不可靠的）。所以就會出現主庫停止寫入之後，從庫複製延遲逐漸增大到某個最高值之後突然變為0的情況

2、官方手冊中對主從拓撲處在一個慢速網路中表現行為描述不太準確（個人推理觀點）：

* 根據公式計算，如果主庫持續不斷產生二進位制日誌（持續不斷有資料變更），則複製延遲的計算結果不會出現誤差（或者說誤差可以忽略不計，因為從庫的系統時鐘是正常向後推進的，除非主從庫的系統時間被改動了），如果在慢速網路中主庫斷斷續續寫入資料，甚至主庫突然停止任何資料寫入，之後實際上主庫並沒有新的資料寫入（也就不會有新的binlog event時間戳產生），但是由於計算公式中並不感知這個變化，所以隨著從庫的系統時鐘繼續向前推進，就會導致在追趕上主庫的資料之前，計算出的延遲時間值越來越大（也就是說此時的複製延遲值是不可靠的）

作者寄語：最後，感謝沃趣科技的同事 @劉雲 幫忙做場景驗證，感謝 @沈剛 幫忙檢視原始碼。

分享