本文主要討論的還是5.7，8.0沒有實際測試，這里簡單記錄。

一、問題說明

最近在處理一個主從問題的時候，發現一個比較奇怪的現象，這個主從是級聯的也就是A->B->C庫，B庫問題處理后先啟動了B庫追數據，然后修復C庫啟動追延遲，這個時候觀察到的B庫和C庫的延遲分別為20000多秒和900多秒，顯然這個差距是非常大的，而級聯又是平時用得很多的一種方式。 這里實際上C庫的延遲應該比B庫更大，那么級聯從庫中C庫的延遲計算到底是怎么樣的呢？

這里我們簡單探討一下，未考慮清楚的地方還請見諒，下面我們也用A B C來代表主庫、從庫1、從庫2。

二、延遲計算和級聯從庫C

一般來講我們在討論延遲的時候，延遲的計算公式大概如下，當然準確來說是單SQL線程（非MTS）下計算延遲的公式。

其中在主庫row格式的binlog其query event中exec time的時間基本為0，因此B庫在計算延遲的時候基本可以在公式中簡化掉。

而在級聯從庫C中，其binlog來自B庫，那么在B庫中的binlog如何記錄的就成了關鍵，那么其有2個關鍵就是：

(1) Event中header中timestamp的時間：這個時間實際上還是主庫的timestamp時間，并不會因為在B庫執行過就是B庫產生binlog的時間。如下：

    thd->set_time(&(common_header->when));
    thd->set_query(query_arg, q_len_arg);
    thd->set_query_id(next_query_id());
    thd->variables.pseudo_thread_id= thread_id;  // for temp tables

這里在B庫應用event的時候，設置了線程的start_time,也就是來自event header，這個實際上就是主庫執行命令的時間，因此B庫中記錄的binlog的event header的timestamp 依舊來自主庫。

(2) query event中exec time的時間：這個時間雖然在主庫幾乎為0，但是B庫在記錄的時候為當前時間 - 線程的start_time，而線程的start_time來自主庫執行命令的時間，因此這個時間大概就是，B庫當前時間-主庫A執行命令的時間，基本就是B庫的在執行query event時刻的延遲時間，如下：

  ulonglong micro_end_time= my_micro_time();//這里獲取當前服務器時間時間
  my_micro_time_to_timeval(micro_end_time, &end_time);

  exec_time= end_time.tv_sec - thd_arg->start_time.tv_sec; //計算exec time

那么級聯從庫C的延遲實際上就是：

從庫C當前時間-(主庫執行命令的時間+B庫的在執行query event時刻的延遲時間)- 主從服務器時間差

好了回到開頭的問題，總結為2點：

• 當B庫延遲很大的時候顯然根據這個公式可以計算出C庫的延遲是比較小的，因為B庫在執行query event時刻的延遲非常大，那么記錄的exec time就很大，到了C庫計算延遲的時候就直接扣除了這部分。
• 當B庫沒什么延遲的時候，C庫計算的延遲基本上就是相對于主庫的延遲，因為這個時候B庫在執行query event時刻的延遲非常小，不會產生太大的誤差。

當然整個邏輯還是說的是時鐘同步的情況下。

三、觀察B庫中的exec time

這里很容易觀察到這種現象，只需要稍微做一下延遲就可以了。 主庫A：

# at 1097
#230518 15:50:04 server id 333900  end_log_pos 1174 CRC32 0xab4d2adc    Query   thread_id=4     exec_time=0     error_code=0
SET TIMESTAMP=1684396204/*!*/;

從庫B：

# at 1069
#230518 15:50:04（timestampm是主庫的） server id 333900  end_log_pos 1132 CRC32 0x483e49b5    Query   thread_id=4     exec_time=48（這里）    error_code=0
SET TIMESTAMP=1684396204/*!*/;

在測試期間還發現B庫，可能 exec_time很大的情況這里簡單描述一下，如下，

#230517 15:33:05 server id 1623306  end_log_pos 1558 CRC32 0x2d7d12fc   Query   thread_id=17    exec_time=4283165634（這里）    error_code=0
SET TIMESTAMP=1684308785/*!*/;

顯然這個是B庫服務器時間落后于A庫的時候，出現相減負數的情況，然后轉非負整數，得到了一個很大的值。這種情況下C的延遲計算也會受到影響。