Seconds_Behind_Master計算原理
當從庫上複制IO程序和複制SQL程序正常運作，且SQL線程處于執行狀态而非等待IO程序同步BINLOG時，複制延遲時間計算如下：
複制延遲時間(Seconds_Behind_Master) = 目前從庫系統時間(time(0)) - 最後binlog的時間戳( mi->rli->last_master_timestamp) - 主從系統時間差(mi->clock_diff_with_master)
最後binlog的時間戳( mi->rli->last_master_timestamp) = 最後binlog事件開始時間(ev->when.tv_sec)+最後binlog事件執行時間((time_t) ev->exec_time)
主從系統時間差(mi->clock_diff_with_master) = 從庫系統時間(time((time_t*) 0)) - 主庫系統時間(UNIX_TIMESTAMP())
上面變量中，從庫系統時間和主庫系統時間都是相對穩定的值，是以主從系統時間差相對穩定，在複制IO程序啟動時計算，是以影響複制延遲的主要因素有：
1、目前從庫系統時間(time(0))，目前從庫系統時間會随時間推移而增長變化，尤其在處理超大事務或超大表DDL變更操作時尤為明顯。
2、最後binlog事件開始時間(ev->when.tv_sec)，當一個BINLOG事件被寫入到BINLOG檔案時，該BINLOG事件的開始時間便已确定，但并行複制和非并行複制兩種複制模式更新“最後binlog的時間戳”存在差異。
3、最後binlog事件執行時間((time_t) ev->exec_time)，當一個BINLOG事件被寫入到BINLOG檔案時，該BINLOG事件的執行時間也已确定，但行格式和語句格式兩種複制格式會導緻時間中記錄的exec_time存在差異。
非并行複制模式下last_master_timestamp更新
當SQL線程從relay log中讀取到binlog event後，會先更新last_master_timestamp，再應用binlog event。
當SQL線程應用完relay log中所有binlog event并處以等待狀态時，會更新last_master_timestamp為0，且複制延遲時間(Seconds_Behind_Master)被指派為0。
并行複制模式下last_master_timestamp更新
并行複制模式下，會建立一個分發隊列GAP來協調多個SQL程序消費不同binlog evenet，并根據條件(參數slave_checkpoint_group，預設512個事務)或定期(參數slave_checkpoint_period，預設300ms)觸發一個checkpoint來推進目前從庫執行事務的最低水位線LWM(low-warter mark)。如隊列中有1-8号事務，而1、2、3、4、6、7号事務已被執行，剩餘5和8号事務正在執行或等待執行，則已執行事務的最低水位線為4。
當執行GAP Checkpoint更新LWM時，會同時更新last_master_timestamp為LWM所在事務結束的EVENT時間，而由于LWM所在事務已被執行，是以是先應用binlog event再更新last_master_timestamp。
由于并行複制模式下不是在BINLOG EVENT執行完成後實時更新last_master_timestamp，是以會導緻last_master_timestamp存在誤差，在沒有延遲情況下仍顯示輕微延遲(slave_checkpoint_period + 事務在備庫執行時間)。
并行複制參數介紹：
slave_checkpoint_period，default 300
Sets the maximum time (in milliseconds) that is allowed to pass before a checkpoint operation is called to update the status of a multithreaded slave as shown by SHOW SLAVE STATUS. Setting this variable has no effect on slaves for which multithreading is not enabled. Setting this variable takes effect for all replication channels immediately, including running channels.
slave_checkpoint_group，default 512
Sets the maximum number of transactions that can be processed by a multithreaded slave before a checkpoint operation is called to update its status as shown by SHOW SLAVE STATUS. Setting this variable has no effect on slaves for which multithreading is not enabled. Setting this variable has no immediate effect. The state of the variable applies on all subsequent START SLAVE commands.
複制格式(BINLOG_FORMAT)對exec_time的影響
在測試環境上執行下面語句：
begin;selectnow();update tb003 set c1=sleep(5) where id=1;select sleep(3);selectnow();update tb003 set c1=sleep(10) where id=2;commit;
基于BINLOG_FORMAT=STATEMENT複制格式的BINLOG解析如下：
# at 14681#190625 23:18:14 server id 1614520 end_log_pos 14746 CRC32 0xdc27cdef GTID last_committed=48 sequence_number=49 rbr_only=noSET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:112';
# at14746#190625 23:17:56 server id 1614520 end_log_pos 14827 CRC32 0xf931e3c0 Query thread_id=3837 exec_time=5 error_code=0
SET TIMESTAMP=1561475876;BEGIN
;
# at14827#190625 23:17:56server id 1614520 end_log_pos 14942 CRC32 0x3bc48f78 Query thread_id=3837 exec_time=5 error_code=0
use `db001`;SET TIMESTAMP=1561475876;update tb003 set c1=sleep(5) where id=1
;
# at14942#190625 23:18:04 server id 1614520 end_log_pos 15058 CRC32 0x053d4b3c Query thread_id=3837 exec_time=10 error_code=0
SET TIMESTAMP=1561475884;update tb003 set c1=sleep(10) where id=2
;
# at15058#190625 23:18:14 server id 1614520 end_log_pos 15089 CRC32 0x5e7dfecd Xid = 11788
COMMIT;
基于BINLOG_FORMAT=ROW複制格式的BINLOG解析如下：
# at 15375#190625 23:24:46 server id 1614520 end_log_pos 15440 CRC32 0x0efa5343 GTID last_committed=50 sequence_number=51 rbr_only=yes;SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:114';
# at15440#190625 23:24:28 server id 1614520 end_log_pos 15513 CRC32 0x2b522fd6 Query thread_id=3837 exec_time=5 error_code=0
SET TIMESTAMP=1561476268;BEGIN
;
# at15513#190625 23:24:28 server id 1614520 end_log_pos 15576 CRC32 0x3753fee7Rows_query
#update tb003 set c1=sleep(5) where id=1# at15576#190625 23:24:28 server id 1614520 end_log_pos 15628 CRC32 0xd8ef6183 Table_map: `db001`.`tb003` mapped to number 229# at15628#190625 23:24:28 server id 1614520 end_log_pos 15698 CRC32 0x70dcd9f1 Update_rows: table id 229flags: STMT_END_F###UPDATE`db001`.`tb003`
###WHERE###@1=1 ###@2=1 ###@3=1561476236 ###SET###@1=1 ###@2=0 ###@3=1561476268 # at15698#190625 23:24:36 server id 1614520 end_log_pos 15762 CRC32 0x64123971Rows_query
#update tb003 set c1=sleep(10) where id=2# at15762#190625 23:24:36 server id 1614520 end_log_pos 15814 CRC32 0xfb3c7742 Table_map: `db001`.`tb003` mapped to number 229# at15814#190625 23:24:36 server id 1614520 end_log_pos 15884 CRC32 0xbd3dacd0 Update_rows: table id 229flags: STMT_END_F###UPDATE`db001`.`tb003`
###WHERE###@1=2 ###@2=1 ###@3=1561476236 ###SET###@1=2 ###@2=0 ###@3=1561476276 # at15884#190625 23:24:46 server id 1614520 end_log_pos 15915 CRC32 0x4d2dba05 Xid = 11799
COMMIT;
從上面的解析結果可以得出：
1、在BEGIN語句開始前的exec_time是事務中第一條語句的執行時間，而非整個事務的執行時間。
2、在ROW複制格式下，exec_time值僅存在事務開始前(BEGIN語句前)，在整個事務中沒有記錄單個語句操作的執行時間。
3、在STATEMENT複制格式下，事務開始前(BEGIN語句前)的包含事務中第一條語句的執行時間，在整個事務中單個語句操作前也包含該語句的執行時間。
4、在事務送出操作前(COMMIT)包含有事務的開始時間和xid，并不包含整個事務的執行時間。
非并行複制模式+STATEMENT複制格式下的複制延遲
測試環境：
MySQL 版本：MySQL 5.7.19主庫設定：
binlog_format= 'STATEMENT'從庫設定:
binlog_format= 'STATEMENT'slave_parallel_type='DATABASE'
主庫系統時間和從庫系統時間完全不同，不存在時間差。
主庫執行：
update tb003set c1=sleep(5) where id=1;
複制複制延遲情況如下：
2019-06-xx xx:xx:xx 從庫IO線程同步，擷取主庫系統時間，主從時間同步，主從系統時間差(mi->clock_diff_with_master)=0秒2019-06-24 20:13:20 主庫開始執行SQL(ev->when.tv_sec="2019-06-24 20:13:20")，主從同步，從庫複制延遲0秒2019-06-24 20:13:25 主庫執行SQL完成，執行時間5秒(ev->exec_time=5秒)，從庫SQL線程等待IO線程擷取BINLOG EVENT，從庫複制延遲0秒2019-06-24 20:13:25主庫将BINLOG推送給從庫，從庫SQL線程等待IO線程擷取BINLOG EVENT，從庫複制延遲0秒2019-06-24 20:13:25從庫IO線程接受到BINLOG EVENT并儲存到RELAY LOG中，從庫SQL線程等待IO線程擷取BINLOG EVENT，從庫複制延遲0秒2019-06-24 20:13:25從庫SQL線程讀取到RELAY LOG中的BINLOG EVENT，并更新last_master_timestamp，複制延遲0秒。
從庫複制延遲時間計算如下：
最後binlog的時間戳( mi->rli->last_master_timestamp) = 最後binlog事件開始時間(ev->when.tv_sec)+最後binlog事件執行時間((time_t) ev->exec_time)= "2019-06-24 20:13:20" + "5秒"
= "2019-06-24 20:13:25"複制延遲時間(Seconds_Behind_Master)= 目前從庫系統時間(time(0)) - 最後binlog的時間戳( mi->rli->last_master_timestamp) - 主從系統時間差(mi->clock_diff_with_master)= "2019-06-24 20:13:25" - "2019-06-24 20:13:25" - "0秒"
=0秒2019-06-24 20:13:26從庫上last_master_timestamp和clock_diff_with_master都未發生變化，從庫時間增加1秒，主從複制延遲為1秒2019-06-24 20:13:27從庫上last_master_timestamp和clock_diff_with_master都未發生變化，從庫時間增加1秒，主從複制延遲為2秒
......2019-06-24 20:13:31從庫上last_master_timestamp和clock_diff_with_master都未發生變化，從庫時間增加1秒，主從複制延遲為5秒2019-06-24 20:13:31 從庫執行到事務的最後COMMIT EVENT，由于該EVENT無exec_time(ev->exec_time=0秒)，更新last_master_timestamp，複制延遲11秒。
從庫複制延遲時間計算如下：
最後binlog的時間戳( mi->rli->last_master_timestamp) = 最後binlog事件開始時間(ev->when.tv_sec)+最後binlog事件執行時間((time_t) ev->exec_time)= "2019-06-24 20:13:20" + "0秒"
= "2019-06-24 20:13:20"複制延遲時間(Seconds_Behind_Master)= 目前從庫系統時間(time(0)) - 最後binlog的時間戳( mi->rli->last_master_timestamp) - 主從系統時間差(mi->clock_diff_with_master)= "2019-06-24 20:13:31" - "2019-06-24 20:13:20" - "0秒"
=11秒2019-06-24 20:13:31 從庫SQL線程應用完RELAY LOG中的所有BINLOG EVENT，SQL線程進入等待狀态，last_master_timestamp被更新為0，從庫複制延遲0秒。
從庫延遲11秒的時間很短，需要重新整理頻率高(每0.1秒掃描一次)的情況下才能發現。
并行複制模式+STATEMENT複制格式下的複制延遲
測試環境：
MySQL 版本：MySQL 5.7.19主庫設定：
binlog_format= 'STATEMENT'從庫設定:
binlog_format= 'STATEMENT'slave_parallel_type='LOGICAL_CLOCK'slave_parallel_workers= 8slave_preserve_commit_order= ON主庫系統時間和從庫系統時間完全不同，不存在時間差。
主庫上執行：
## 執行周期 2019-06-26 09:32:53--2019-06-26 09:33:03,執行時間10秒
update tb003 set c1=SLEEP(10) where id=1;
## 執行周期2019-06-26 09:33:03--2019-06-26 09:33:13,執行時間10秒
update tb003 set c1=SLEEP(10) where id=2;
## 執行周期2019-06-26 09:33:13--2019-06-26 09:33:23,執行時間10秒
update tb003 set c1=SLEEP(10) where id=3;
從庫上複制延遲：
## 從庫上Relay_Master_Log_File未發送變化，是以隻描述Exec_Master_Log_Pos變化2019-06-26 09:32:53之前 Exec_Master_Log_Pos=18287,Seconds_Behind_Master=0
2019-06-26 09:32:53 --2019-06-26 09:33:13 Exec_Master_Log_Pos=18287,Seconds_Behind_Master=0
2019-06-26 09:33:14 --2019-06-26 09:33:23 Exec_Master_Log_Pos=18631,Seconds_Behind_Master 從10增長到19
2019-06-26 09:33:24 --2019-06-26 09:33:33 Exec_Master_Log_Pos=18975,Seconds_Behind_Master 從10增長到19
2019-06-26 09:33:34之後 Exec_Master_Log_Pos=19319,Seconds_Behind_Master=0
主庫BINLOG解析結果為：
# at 18287#190626 9:32:53 server id 1614520 end_log_pos 18352 CRC32 0x9bfcc652 GTID last_committed=59 sequence_number=60 rbr_only=noSET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:123';
# at18352#190626 9:32:53 server id 1614520 end_log_pos 18433 CRC32 0x0244bb1a Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512773;BEGIN
;
# at18433#190626 9:32:53 server id 1614520 end_log_pos 18549 CRC32 0xea35ba85 Query thread_id=3848 exec_time=10 error_code=0
use `db001`;SET TIMESTAMP=1561512773;update tb003 set c1=SLEEP(10) where id=1
;
# at18549#190626 9:32:53 server id 1614520 end_log_pos 18631 CRC32 0x0aafadd6 Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512773;COMMIT
;
# at18631#190626 9:33:03 server id 1614520 end_log_pos 18696 CRC32 0xcf5f7255 GTID last_committed=60 sequence_number=61 rbr_only=noSET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:124';
# at18696#190626 9:33:03 server id 1614520 end_log_pos 18777 CRC32 0x9b5bd9a2 Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512783;BEGIN
;
# at18777#190626 9:33:03 server id 1614520 end_log_pos 18893 CRC32 0xcb74bf8b Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512783;update tb003 set c1=SLEEP(10) where id=2
;
# at18893#190626 9:33:03 server id 1614520 end_log_pos 18975 CRC32 0x2f80ec1e Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512783;COMMIT
;
# at18975#190626 9:33:13 server id 1614520 end_log_pos 19040 CRC32 0x16f3eadd GTID last_committed=61 sequence_number=62 rbr_only=noSET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:125';
# at19040#190626 9:33:13 server id 1614520 end_log_pos 19121 CRC32 0x52c49fbe Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512793;BEGIN
;
# at19121#190626 9:33:13 server id 1614520 end_log_pos 19237 CRC32 0x5638a3eb Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512793;update tb003 set c1=SLEEP(10) where id=3
;
# at19237#190626 9:33:13 server id 1614520 end_log_pos 19319 CRC32 0x54716796 Query thread_id=3848 exec_time=10 error_code=0
SET TIMESTAMP=1561512793;COMMIT
;
複制延遲計算方式：
在2019-06-26 09:32:50 -- 2019-06-26 09:33:03期間，Exec_Master_Log_Pos=18287，從庫上分發隊列GAQ為空，将last_master_timestamp設定為0，Seconds_Behind_Master為0。
在2019-06-26 09:33:04 -- 2019-06-26 09:33:13期間，分發隊列GAQ的CHECKPOINT沒有推進，last_master_timestamp未被更新，Exec_Master_Log_Pos還是保持18287，是以Seconds_Behind_Master為0。
在2019-06-26 09:33:14 -- 2019-06-26 09:33:23期間，Exec_Master_Log_Pos= 18631 ，對應的事務開始時間"2019-06-26 09:32:53",執行時間10秒。
在2019-06-26 09:33:18時的從庫複制延遲時間計算如下：
最後binlog的時間戳( mi->rli->last_master_timestamp) = 最後binlog事件開始時間(ev->when.tv_sec)+最後binlog事件執行時間((time_t) ev->exec_time)
= "2019-06-26 09:32:53" + "10秒"
= "2019-06-26 09:33:03"
複制延遲時間(Seconds_Behind_Master) = 目前從庫系統時間(time(0)) - 最後binlog的時間戳( mi->rli->last_master_timestamp) - 主從系統時間差(mi->clock_diff_with_master)
= "2019-06-26 09:33:18" - "2019-06-26 09:33:03" - "0秒"
= 15秒