MySQL · 答疑解惑 · 備庫Seconds_Behind_Master計算 · 數據庫內核月報

## 背景在mysql主備環境下，主備同步過程如下，主庫更新產生binlog, 備庫io線程拉取主庫binlog生成relay log。備庫sql線程執行relay log從而保持和主庫同步。 ![](https://box.kancloud.cn/2016-04-11_570b485f15d7c.png) 理論上主庫有更新時，備庫都存在延遲，且延遲時間為備庫執行時間+網絡傳輸時間即t4-t2。那么mysql是怎么來計算備庫延遲的？先來看show slave status中的一些信息，io線程拉取主庫binlog的位置： ~~~ Master_Log_File: mysql-bin.000001 Read_Master_Log_Pos: 107 ~~~ sql線程執行relay log的位置： ~~~ Relay_Log_File: slave-relay.000003 Relay_Log_Pos: 253 ~~~ sql線程執行的relay log相對于主庫binlog的位置： ~~~ Relay_Master_Log_File: mysql-bin.000001 Exec_Master_Log_Pos: 107 ~~~ ## 源碼實現 Seconds_Behind_Master計算的源碼實現如下： ~~~ 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); protocol->store((longlong)(mi->rli->last_master_timestamp ? max(0L, time_diff) : 0)); } ~~~ 大致可以看出是通過時間和位點來計算的，下面詳細分析下。 if里面條件表示如果io線程拉取主庫binlog的位置和sql線程執行的relay log相對于主庫binlog的位置相等，那么認為延遲為0。一般情況下，io線程比sql線程快。但如果網絡狀況特別差，導致sql線程需等待io線程的情況，那么這兩個位點可能相等，會導致誤認為延遲為0。再看else里： * `clock_diff_with_master` io線程啟動時會向主庫發送sql語句“SELECT UNIX_TIMESTAMP()”，獲取主庫當前時間，然而用備庫當前時間減去此時間或者主備時間差值即為`clock_diff_with_master`。這里如果有用戶中途修改了主庫系統時間或修改了timestamp變量，那么計算出備庫延遲時間就是不準確的。 * `last_master_timestamp` 表示主庫執行binlog事件的時間。此時間在并行復制和非并行復制時的計算方法是不同的非并行復制：備庫sql線程讀取了relay log中的event，event未執行之前就會更新`last_master_timestamp`，這里時間的更新是以event為單位。 ~~~ rli->last_master_timestamp= ev->when.tv_sec + (time_t) ev->exec_time; ~~~ ev->when.tv_sec表示事件的開始時間。exec_time指事件在主庫的執行時間，只有`Query_log_event`和`Load_log_event`才會統計exec_time。另外一種情況是sql線程在等待io線程獲取binlog時，會將`last_master_timestamp`設為0，按上面的算法Seconds_Behind_Master為0，此時任務備庫是沒有延遲的。并行復制： > 并行復制有一個分發隊列gaq，sql線程將binlog事務讀取到gaq，然后再分發給worker線程執行。并行復制時，binlog事件是并發穿插執行的，gaq中有一個checkpoint點稱為lwm, lwm之前的binlog都已經執行，而lwm之后的binlog有些執行有些沒有執行。 > 假設worker線程數為2，gap有1,2,3,4,5,6,7,8個事務。worker 1已執行的事務為1 4 6, woker 2執行的事務為2 3 ，那么lwm為4。并行復制更新gap checkpiont時，會推進lwm點，同時更新`last_master_timestamp`為lwm所在事務結束的event的時間。因此，并行復制是在事務執行完成后才更新`last_master_timestamp`，更新是以事務為單位。同時更新gap checkpiont還受`slave_checkpoint_period`參數的影響。這導致并行復制下和非并行復制統計延遲存在差距，差距可能為`slave_checkpoint_period`?+ 事務在備庫執行的時間。這就是為什么在并行復制下有時候會有很小的延遲，而改為非并行復制時反而沒有延遲的原因。另外當sql線程等待io線程時且gaq隊列為空時，會將`last_master_timestamp`設為0。同樣此時認為沒有延遲，計算得出`seconds_Behind_Master`為0。 ## 位點信息維護 * io線程拉取binlog的位點 ~~~ Master_Log_File 讀取到主庫ROTATE_EVENT時會更新(process_io_rotate) Read_Master_Log_Pos:io線程每取到一個event都會從event中讀取pos信息并更新 mi->set_master_log_pos(mi->get_master_log_pos() + inc_pos); ~~~ * sql線程執行relay log的位置 ~~~ Relay_Log_File sql線程處理ROTATE_EVENT時更新(Rotate_log_event::do_update_pos) Relay_Log_Pos: 非并行復制時，每個語句執行完成更新(stmt_done) 并行復制時，事務完成時更新(Rotate_log_event::do_update_pos/ Xid_log_event::do_apply_event/stmt_done) ~~~ * sql線程執行的relay log相對于主庫binlog的位置 ~~~ Relay_Master_Log_File sql線程處理ROTATE_EVENT時更新(Rotate_log_event::do_update_pos) Exec_Master_Log_Pos 和Relay_Log_Pos同時更新非并行復制時，每個語句執行完成更新(stmt_done) 并行復制時，事務完成時更新(Rotate_log_event::do_update_pos/ Xid_log_event::do_apply_event/stmt_done) ~~~ 談到位點更新就有必要說到兩個事件：HEARTBEAT_LOG_EVENT 和 ROTATE_EVENT。 * HEARTBEAT_LOG_EVENT HEARTBEAT_LOG_EVENT我們的了解一般作用是，在主庫沒有更新的時候，每隔`master_heartbeat_period`時間都發送此事件保持主庫與備庫的連接。而HEARTBEAT_LOG_EVENT另一個作用是，在gtid模式下，主庫有些gtid備庫已經執行同時，這些事件雖然不需要再備庫執行，但讀取和應用binglog的位點還是要推進。因此，這里將這類event轉化為HEARTBEAT_LOG_EVENT，由HEARTBEAT_LOG_EVENT幫助我們推進位點。 * ROTATE_EVENT 主庫binlog切換產生的ROTATE_EVENT，備庫io線程收到時會也有切換relay log。此rotate也會記入relay log，sql線程執行ROTATE_EVENT只更新位點信息。備庫io線程接受主庫的HEARTBEAT_LOG_EVENT，一般不用戶處理。前面提到，gtid模式下，當HEARTBEAT_LOG_EVENT的位點大于當前記錄的位點時，會構建一個ROTATE_EVENT,從而讓sql線程推進位點信息。 ~~~ if (mi->is_auto_position() && mi->get_master_log_pos() < hb。log_pos && mi->get_master_log_name() != NULL) { mi->set_master_log_pos(hb。log_pos); write_ignored_events_info_to_relay_log(mi->info_thd, mi); //構建ROTATE_EVENT ...... } ~~~ 另外，在`replicate_same_server_id`為0時，備庫接收到的binlog與主庫severid相同時，備庫會忽略此binlog，但位點仍然需要推進。為了效率，此binlog不需要記入relay log。而是替換為ROTATE_EVENT來推進位點。 ## 延遲現象初始主備是同步的，且沒有任何更新。假設主備庫執行某個DDL在都需要30s，執行某個大更新事務(例如insert..select * from )需要30s。不考慮網絡延遲。 ![](https://box.kancloud.cn/2016-04-11_570b485f299f5.png) * 非并行復制時執行DDL：t2時刻主庫執行完，t2時刻備庫執行show slave status，Seconds_Behind_Master值為0。同時t2至t3 Seconds_Behind_Master依次增大至30，然后跌0。執行大事務：t2時刻主庫執行完，t2時刻備庫執行show slave status，Seconds_Behind_Master值為30。同時t2至t3 Seconds_Behind_Master依次增大至60，然后跌0。以上區別的原因是exec_time只有`Query_log_event`和`Load_log_event`才會統計，普通更新沒有統計導致。 * 并行復制時執行DDL：t2時刻主庫執行完，t2至t3備庫執行show slave status，Seconds_Behind_Master值一直為0 執行大事務：t2時刻主庫執行完，t2至t3備庫執行show slave status，Seconds_Behind_Master值一直為0 這是因為執行語句之前主備是完全同步的，gaq隊列為空，會將`last_master_timestamp`設為0。而執行DDL過程中，gap checkpoint一直沒有推進，`last_master_timestamp`一直未0，直到DDL或大事務完成。所以t2至t3時刻Seconds_Behind_Master值一直為0。而t3時刻有一瞬間`last_master_timestamp`是會重置的，但又因`slave_checkpoint_period`會推進checkpoint,gaq隊列變為空，會將`last_master_timestamp`重設為0。因此t3時刻可能看到瞬間有延遲(對于DDL是延遲30s,對于大事務時延遲60s)。這似乎很不合理，gaq隊列為空，會將`last_master_timestamp`設為0,這條規則實際可以去掉。 ## 相關bug [BUG#72376](http://bugs.mysql.com/bug%E3%80%82php?id=72376), PREVIOUS_GTIDS_LOG_EVENT 事件記錄在每個binlog的開頭，表示先前所有文件的gtid集合。relay-log本身event記錄是主庫的時間，但relay log開頭的PREVIOUS_GTIDS_LOG_EVENT事件，是在slave端生成的，時間也是以slave為準的。因此不能用此時間計算`last_master_timestamp`。修復方法是在relay log寫PREVIOUS_GTIDS_LOG_EVENT事件是標記是relay log產生的，在統計`last_master_timestamp`時，發現是relay產生的事件則忽略統計。 ~~~ if (is_relay_log) prev_gtids_ev。set_relay_log_event(); ...... if (!(ev->is_artificial_event()||...)) rli->last_master_timestamp= ev->when。tv_sec + (time_t) ev->exec_time; ~~~ ## 總結 Seconds_Behind_Master的計算并不準確和可靠。并行復制下Seconds_Behind_Master值比非并行復制時偏大。因此當我們判斷備庫是否延遲時，根據Seconds_Behind_Master=0不一定可靠。但是，當我們進行主備切換時，在主庫停寫的情況下，我們可以根據位點來判斷是否完全同步。如果(Relay_Master_Log_File, Exec_Master_Log_Pos)和(Relay_Master_Log_File, Read_Master_Log_Pos)位置相等且Seconds_Behind_Master=0，那么我們可以認為主備是完成同步的，可以進行切換。