MySQL Replication--复制延迟03--Seconds_Behind_Master计算

测试方法：

1、在主库上执行耗时的UPDATE操作

2、在从库上每秒一次监控复制延迟（Seconds_Behind_Master）的值

测试环境：

1、主库和从库时间同步，无系统时间差。

2、主库和从库使用BINLOG_FORMAT='STATEMENT'复制格式

3、主库上除测试脚本执行外，无其他事务操作。

测试1：主库上单独执行一条执行时间为10秒的UPDATE语句

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 19:43:59 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(10) where id=2;
Query OK, 1 row affected, 1 warning (10.05 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 19:44:09 |
+---------------------+

复制延迟情况如下：

测试2：主库上连续执行三条执行时间为10秒的UPDATE语句

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:13:19 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(10) where id=7;
Query OK, 1 row affected, 1 warning (10.04 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:13:29 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(10) where id=8;
Query OK, 1 row affected, 1 warning (10.05 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:13:39 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(10) where id=9;
Query OK, 1 row affected, 1 warning (10.04 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:13:49 |
+---------------------+

复制延迟情况如下：

测试三：主库上连续执行四条执行时间不同的UPDATE语句

select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:27:08 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(5) where id=1;
Query OK, 1 row affected, 1 warning (5.04 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:27:13 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(10) where id=2;
Query OK, 1 row affected, 1 warning (10.05 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:27:23 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(20) where id=3;
Query OK, 1 row affected, 1 warning (20.05 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:27:43 |
+---------------------+
1 row in set (0.00 sec)

mysql> update tb003 set c1=SLEEP(5) where id=4;
Query OK, 1 row affected, 1 warning (5.05 sec)
Rows matched: 1  Changed: 1  Warnings: 1

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2019-06-24 20:27:49 |
+---------------------+
1 row in set (0.00 sec)

复制延迟情况，仅在2019-06-24 20:28:04到2019-06-24 20:28:08期间出现41秒到45秒的延迟。

从库开启general_log后抓到数据为：

2019-06-24T20:25:59.718169+08:00      731 Query    COMMIT /* implicit, from Xid_log_event */
2019-06-24T20:27:18.920529+08:00      731 Query    update tb003 set c1=SLEEP(5) where id=1
2019-06-24T20:27:18.920575+08:00      731 Query    COMMIT /* implicit, from Xid_log_event */
2019-06-24T20:27:33.967500+08:00      731 Query    update tb003 set c1=SLEEP(10) where id=2
2019-06-24T20:27:33.967543+08:00      731 Query    COMMIT /* implicit, from Xid_log_event */
2019-06-24T20:28:04.022589+08:00      731 Query    update tb003 set c1=SLEEP(20) where id=3
2019-06-24T20:28:04.022633+08:00      731 Query    COMMIT /* implicit, from Xid_log_event */
2019-06-24T20:28:09.069716+08:00      731 Query    update tb003 set c1=SLEEP(5) where id=4
2019-06-24T20:28:09.069760+08:00      731 Query    COMMIT /* implicit, from Xid_log_event */

出现延迟时执行的是SLEEP(5)的语句，而该语句在主库上的开始时间是2019-06-24 20:27:43，在从库上执行结束时间是2019-06-24 20:28:09,两者差距26秒。

从库上binlog解析信息为：

# at 1399
#190624 20:27:08 server id 1614520  end_log_pos 1464 CRC32 0x6c08195e     GTID    last_committed=4    sequence_number=5    rbr_only=no
SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:59'/*!*/;
# at 1464
#190624 20:27:08 server id 1614520  end_log_pos 1545 CRC32 0x5eaaf060     Query    thread_id=56    exec_time=10    error_code=0
SET TIMESTAMP=1561379228/*!*/;
BEGIN
/*!*/;
# at 1545
#190624 20:27:08 server id 1614520  end_log_pos 1660 CRC32 0x00b1382a     Query    thread_id=56    exec_time=10    error_code=0
SET TIMESTAMP=1561379228/*!*/;
update tb003 set c1=SLEEP(5) where id=1
/*!*/;
# at 1660
#190624 20:27:08 server id 1614520  end_log_pos 1691 CRC32 0x2664d179     Xid = 2378
COMMIT/*!*/;
# at 1691
#190624 20:27:13 server id 1614520  end_log_pos 1756 CRC32 0x79c91f33     GTID    last_committed=5    sequence_number=6    rbr_only=no
SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:60'/*!*/;
# at 1756
#190624 20:27:13 server id 1614520  end_log_pos 1837 CRC32 0x41677ead     Query    thread_id=56    exec_time=20    error_code=0
SET TIMESTAMP=1561379233/*!*/;
BEGIN
/*!*/;
# at 1837
#190624 20:27:13 server id 1614520  end_log_pos 1953 CRC32 0x8f3a5813     Query    thread_id=56    exec_time=20    error_code=0
SET TIMESTAMP=1561379233/*!*/;
update tb003 set c1=SLEEP(10) where id=2
/*!*/;
# at 1953
#190624 20:27:13 server id 1614520  end_log_pos 1984 CRC32 0x4565c1ab     Xid = 2410
COMMIT/*!*/;
# at 1984
#190624 20:27:23 server id 1614520  end_log_pos 2049 CRC32 0xee8d5574     GTID    last_committed=6    sequence_number=7    rbr_only=no
SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:61'/*!*/;
# at 2049
#190624 20:27:23 server id 1614520  end_log_pos 2130 CRC32 0xd09cf5d3     Query    thread_id=56    exec_time=41    error_code=0
SET TIMESTAMP=1561379243/*!*/;
BEGIN
/*!*/;
# at 2130
#190624 20:27:23 server id 1614520  end_log_pos 2246 CRC32 0x6b8cebd8     Query    thread_id=56    exec_time=41    error_code=0
SET TIMESTAMP=1561379243/*!*/;
update tb003 set c1=SLEEP(20) where id=3
/*!*/;
# at 2246
#190624 20:27:23 server id 1614520  end_log_pos 2277 CRC32 0x0ccba269     Xid = 2472
COMMIT/*!*/;
# at 2277
#190624 20:27:43 server id 1614520  end_log_pos 2342 CRC32 0x33e997a6     GTID    last_committed=7    sequence_number=8    rbr_only=no
SET @@SESSION.GTID_NEXT= '025fd638-89ea-11e9-a749-40f2e9cf3aaa:62'/*!*/;
# at 2342
#190624 20:27:43 server id 1614520  end_log_pos 2423 CRC32 0x8c430e8d     Query    thread_id=56    exec_time=26    error_code=0
SET TIMESTAMP=1561379263/*!*/;
BEGIN
/*!*/;
# at 2423
#190624 20:27:43 server id 1614520  end_log_pos 2538 CRC32 0xec0d57ca     Query    thread_id=56    exec_time=26    error_code=0
SET TIMESTAMP=1561379263/*!*/;
update tb003 set c1=SLEEP(5) where id=4
/*!*/;
# at 2538
#190624 20:27:43 server id 1614520  end_log_pos 2569 CRC32 0x020ef86f     Xid = 2531
COMMIT/*!*/;

总结：

别问我Seconds_Behind_Master如何计算，也别问我为啥不准，真心不懂！

MySQL Replication--复制延迟03--Seconds_Behind_Master计算

猜你喜欢