MySQL Replication--复制延迟03--Seconds_Behind_Master计算
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; select now(); update tb003 set c1=sleep(5) where id=1; select sleep(3); select now(); 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=no SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:112'/*!*/; # at 14746 #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 /*!*/; # at 14827 #190625 23:17:56 server 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 /*!*/; # at 14942 #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 /*!*/; # at 15058 #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 /*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/; SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:114'/*!*/; # at 15440 #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 /*!*/; # at 15513 #190625 23:24:28 server id 1614520 end_log_pos 15576 CRC32 0x3753fee7 Rows_query # update tb003 set c1=sleep(5) where id=1 # at 15576 #190625 23:24:28 server id 1614520 end_log_pos 15628 CRC32 0xd8ef6183 Table_map: `db001`.`tb003` mapped to number 229 # at 15628 #190625 23:24:28 server id 1614520 end_log_pos 15698 CRC32 0x70dcd9f1 Update_rows: table id 229 flags: STMT_END_F ### UPDATE `db001`.`tb003` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=1 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561476236 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### SET ### @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=0 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561476268 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ # at 15698 #190625 23:24:36 server id 1614520 end_log_pos 15762 CRC32 0x64123971 Rows_query # update tb003 set c1=sleep(10) where id=2 # at 15762 #190625 23:24:36 server id 1614520 end_log_pos 15814 CRC32 0xfb3c7742 Table_map: `db001`.`tb003` mapped to number 229 # at 15814 #190625 23:24:36 server id 1614520 end_log_pos 15884 CRC32 0xbd3dacd0 Update_rows: table id 229 flags: STMT_END_F ### UPDATE `db001`.`tb003` ### WHERE ### @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=1 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561476236 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ ### SET ### @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */ ### @2=0 /* INT meta=0 nullable=1 is_null=0 */ ### @3=1561476276 /* TIMESTAMP(0) meta=0 nullable=0 is_null=0 */ # at 15884 #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 tb003 set 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 = 8 slave_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=no SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:123'/*!*/; # at 18352 #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 /*!*/; # at 18433 #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 /*!*/; # at 18549 #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 /*!*/; # at 18631 #190626 9:33:03 server id 1614520 end_log_pos 18696 CRC32 0xcf5f7255 GTID last_committed=60 sequence_number=61 rbr_only=no SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:124'/*!*/; # at 18696 #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 /*!*/; # at 18777 #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 /*!*/; # at 18893 #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 /*!*/; # at 18975 #190626 9:33:13 server id 1614520 end_log_pos 19040 CRC32 0x16f3eadd GTID last_committed=61 sequence_number=62 rbr_only=no SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:125'/*!*/; # at 19040 #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 /*!*/; # at 19121 #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 /*!*/; # at 19237 #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秒
