正文
在衡量主从延迟时，Seconds_Behind_Master 是一个我们常常会看，也比较关注的指标。
虽然关于它不准确的说法很多，但具体哪里不准确，很多人就语焉不详了。
以至于到最后，不准确成了它的代名词，它本身的意义反而被忽略了。
所以就出现了一个奇怪的现象：我们明明内心对它是抗拒的，却还总是基于它来定位问题。
但事实上，存在即合理。在绝大多数情况下，Seconds_Behind_Master 还是能很好的反映主从延迟情况。
本文主要包括以下几部分：
从源码角度分析 Seconds_Behind_Master 的实现逻辑。
为什么 STATEMENT 格式和 ROW 格式的计算方法不一样？
Seconds_Behind_Master 的局限性。
如何监控主从延迟。
这里会重点介绍两种方案：pt-heartbeat 和 MySQL 8.0 原生的解决方案。
如何解读 Seconds_Behind_Master
首先我们从源码的角度来看看 Seconds_Behind_Master 的实现逻辑及局限性。
mysql-8.0.25/sql/rpl_slave.cc
/*
if (SQL thread is running)
{
if (SQL thread processed all the available relay log)
{
if (IO thread is running)
print 0;
else
print NULL;
}
else
compute Seconds_Behind_Master;
}
else
print NULL;
*/
以上是计算 Seconds_Behind_Master 的伪代码。
通过上述代码，我们可以得到如下结论。
但是上面的伪代码并没有说明 Seconds_Behind_Master 具体是如何计算的，所以接下来我们看看相关的源码。
mysql-8.0.25/sql/rpl_slave.cc
if (mi->rli->slave_running) {
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(nullptr) - mi->rli->last_master_timestamp) -
mi->clock_diff_with_master);
protocol->store(
(longlong)(mi->rli->last_master_timestamp ? max(0L, time_diff) : 0));
}
} else {
protocol->store_null();
}
通过对比伪代码和源码，不难看出 Seconds_Behind_Master 的计算逻辑是由如下代码实现的。
long time_diff = ((long)(time(nullptr) - mi->rli->last_master_timestamp) -
mi->clock_diff_with_master);
protocol->store(
(longlong)(mi->rli->last_master_timestamp ? max(0L, time_diff) : 0));
在这段代码里，
time(0)：从库当前的系统时间。
mi->rli->last_master_timestamp：SQL 线程当前重放的事务在主库开始执行的时间戳，具体到 binlog 中，即事件注释部分的时间戳，如下面这个事件中的 210912 9:53:25 。
#210912 9:53:25 server id 1 end_log_pos 26045 CRC32 0xcca7e8ab GTID last_committed=66 sequence_number=67 rbr_only=no
mi->clock_diff_with_master：IO 线程启动时，主从之间的系统时间差。
注意，如果 IO 线程启动后调整过系统时间，需重启复制，否则会影响 Seconds_Behind_Master 的计算结果。
综合起来，Seconds_Behind_Master = 从库当前的系统时间 - SQL 线程当前重放的事务在主库的开始时间戳 - 主从之间的系统时间差。
STATEMENT 和 ROW 格式的计算方法不一样
在具体计算时，针对 STATEMENT 格式和 ROW 格式的计算方法又不相同，看下面这个测试。
STATEMENT 格式
首先针对 STATEMENT 格式进行测试。
（1）测试语句。
mysql> set session binlog_format='statement';
Query OK, 0 rows affected (0.00 sec)
mysql> delete from sbtest.sbtest1 where id=1;
Query OK, 1 row affected (8.95 sec)
（2）每隔 1 秒采集一次从库 Seconds_Behind_Master 的值。
# while true; do mysql -e 'show slave status\G' |grep -E 'Seconds_Behind_Master|Relay_Log_File|Relay_Log_Pos';date;sleep 1;done
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 26181
Seconds_Behind_Master: 0
Sun Sep 12 09:53:34 CST 2021
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 26181
Seconds_Behind_Master: 1
...
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 26181
Seconds_Behind_Master: 8
Sun Sep 12 09:53:42 CST 2021
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 26181
Seconds_Behind_Master: 9
Sun Sep 12 09:53:43 CST 2021
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 26495
Seconds_Behind_Master: 0
Sun Sep 12 09:53:44 CST 2021
（3）查看 DELETE 操作对应的 relay log 的内容。
# at 26181
#210912 9:53:25 server id 1 end_log_pos 26045 CRC32 0xcca7e8ab GTID last_committed=66 sequence_number=67 rbr_only=no original_committed_timestamp=1631411614812820 immediate_commit_timestamp=1631411614812820 transaction_length=314
# original_commit_timestamp=1631411614812820 (2021-09-12 09:53:34.812820 CST)
# immediate_commit_timestamp=1631411614812820 (2021-09-12 09:53:34.812820 CST)
/*!80001 SET @@session.original_commit_timestamp=1631411614812820*//*!*/;
/*!80014 SET @@session.original_server_version=80025*//*!*/;
/*!80014 SET @@session.immediate_server_version=80025*//*!*/;
SET @@SESSION.GTID_NEXT= 'bd6b3216-04d6-11ec-b76f-000c292c1f7b:67'/*!*/;
# at 26260
#210912 9:53:25 server id 1 end_log_pos 26131 CRC32 0x6332aa0b Query thread_id=85 exec_time=9 error_code=0
SET TIMESTAMP=1631411605/*!*/;
SET @@session.pseudo_thread_id=85/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 26346
#210912 9:53:25 server id 1 end_log_pos 26249 CRC32 0x820b04fb Query thread_id=85 exec_time=9 error_code=0
use `sbtest`/*!*/;
SET TIMESTAMP=1631411605/*!*/;
delete from sbtest.sbtest1 where id=1
/*!*/;
# at 26464
#210912 9:53:25 server id 1 end_log_pos 26280 CRC32 0x3328f601 Xid = 45170
COMMIT/*!*/;
这个事务在主库开始执行的时间戳是 210912 9:53:25。
当 Seconds_Behind_Master 达到最大值时，从库的系统时间是 09:53:43，且主从时间一致。
09:53:43 减去 9:53:25 等于 18 秒，但为何此时 Seconds_Behind_Master 的值是 9 秒呢？
ROW 格式
接下来针对 ROW 格式进行测试。
（1）测试语句。
mysql> set session binlog_format='row';
Query OK, 0 rows affected (0.00 sec)
mysql> delete from sbtest.sbtest1 where id=1;
Query OK, 1 row affected (9.00 sec)
（2）每隔 1 秒采集一次从库 Seconds_Behind_Master 的值。
# while true; do mysql -e 'show slave status\G' |grep -E 'Seconds_Behind_Master|Relay_Log_File|Relay_Log_Pos';date;sleep 1;done
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 27796
Seconds_Behind_Master: 0
Sun Sep 12 10:07:27 CST 2021
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 27796
Seconds_Behind_Master: 10
Sun Sep 12 10:07:28 CST 2021
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 27796
Seconds_Behind_Master: 11
Sun Sep 12 10:07:29 CST 2021
...
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 27796
Seconds_Behind_Master: 24
Sun Sep 12 10:07:42 CST 2021
Relay_Log_File: node2-relay-bin.000003
Relay_Log_Pos: 28275
Seconds_Behind_Master: 0
Sun Sep 12 10:07:43 CST 2021
（3）查看 DELETE 操作对应的 relay log 的内容。
# at 27796
#210912 10:07:18 server id 1 end_log_pos 27660 CRC32 0xfdbbc98a GTID last_committed=70 sequence_number=71 rbr_only=yes original_committed_timestamp=1631412447730254 immediate_commit_timestamp=1631412447730254 transaction_length=479
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1631412447730254 (2021-09-12 10:07:27.730254 CST)
# immediate_commit_timestamp=1631412447730254 (2021-09-12 10:07:27.730254 CST)
/*!80001 SET @@session.original_commit_timestamp=1631412447730254*//*!*/;
/*!80014 SET @@session.original_server_version=80025*//*!*/;
/*!80014 SET @@session.immediate_server_version=80025*//*!*/;
SET @@SESSION.GTID_NEXT= 'bd6b3216-04d6-11ec-b76f-000c292c1f7b:71'/*!*/;
# at 27875
#210912 10:07:18 server id 1 end_log_pos 27737 CRC32 0xd6f1066e Query thread_id=85 exec_time=9 error_code=0
SET TIMESTAMP=1631412438/*!*/;
SET @@session.pseudo_thread_id=85/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 27952
#210912 10:07:18 server id 1 end_log_pos 27804 CRC32 0x366916c9 Table_map: `sbtest`.`sbtest1` mapped to number 207
# at 28019
#210912 10:07:18 server id 1 end_log_pos 28029 CRC32 0x272cf311 Delete_rows: table id 207 flags: STMT_END_F
### DELETE FROM `sbtest`.`sbtest1`
### WHERE
### @1=1
### @2=4992833
### @3='83868641912-28773972837-60736120486-75162659906-27563526494-20381887404-41576422241-93426793964-56405065102-33518432330'
### @4='67847967377-48000963322-62604785301-91415491898-96926520291'
# at 28244
#210912 10:07:18 server id 1 end_log_pos 28060 CRC32 0x196ee952 Xid = 45178
COMMIT/*!*/;
同样取 Seconds_Behind_Master 最大值的时间戳进行计算 。
从库的主机时间 10:07:42，事务开始执行的时间是 10:07:18 ，且主从时间同步。
10:07:42 减去 10:07:18 等于 24 秒 ，和 Seconds_Behind_Master 最大值 24 秒基本吻合。
为何和 STATEMENT 格式下的输出不一样呢？
为什么两者的计算方法不一样
细心的读者可能会发现，在 ROW 格式下，Seconds_Behind_Master 第一次出现延迟的延迟时间是 10 秒，而在 STATEMENT 格式下，则是 1 秒 。实际上，这是由二进制日志事件的类型决定的。
对于 QUERY_EVENT（包括 DDL 和 STATEMENT 格式下的 DML 操作），在计算 mi->rli->last_master_timestamp 时，会加上 QUERY_EVENT 中的 exec_time ，即 mi->rli->last_master_timestamp = SQL线程当前重放的事务在主库的开始时间戳 + exec_time 。
所以，在 STATEMENT 格式下，Seconds_Behind_Master = 从库的系统时间 - SQL 线程当前重放的事务在主库的开始时间戳 - exec_time - 主从之间的系统时间差。
这也就是为什么在 STATEMENT 格式下，Seconds_Behind_Master 会从 1 秒开始，以及当从库的系统时间减去 SQL 线程当前重放的事务在主库的开始时间戳 等于 18 秒时，Seconds_Behind_Master 只有 9 秒。
而对于 ROWS_EVENT ，它没有记录 exec_time 。所在，在 ROW 格式下，Seconds_Behind_Master = 从库的系统时间 - SQL线程当前重放的事务在主库的开始时间戳 - 主从之间的系统时间差。
这也就是为什么在 ROW 格式下，Seconds_Behind_Master 第一次出现延迟的延迟时间就是 10 秒。
Seconds_Behind_Master 的局限性
通过上面的分析，我们对 Seconds_Behind_Master 已经有了比较深入的了解。接下来，我们说说它的局限性。
1、Seconds_Behind_Master 只能衡量 SQL 线程的延迟情况，不能衡量 IO 线程的延迟情况。
因为是从 relay log 中获取 SQL 线程当前重放的事务在主库开始执行的时间戳，考虑以下三种场景：
在上面三个场景中，因从库的 relay log 已重放完，所以 Seconds_Behind_Master 会显示为 0 。但实际上，从库已经延迟了。
2、对于 STATEMENT 格式和 ROW 格式的事务，Seconds_Behind_Master 的计算逻辑并不一样。如果不熟悉这两者之间的区别，就很容易感到困惑。
3、不适用于级联复制场景。如果二级从库出现了延迟，对于其它级别的从库，Seconds_Behind_Master 大概率会为 0。
如何监控主从延迟
既然我们看到了 Seconds_Behind_Master 作为主从延迟监控指标的局限性，那么线上又该如何监控主从延迟呢？
在 MySQL 8.0 之前，业界通用的解决方案是 pt-heartbeat 。
pt-heartbeat
pt-heartbeat 是 Percona 公司开源的 Percona Toolkit 中的一个工具。
关于什么是 Percona Toolkit 及安装方法，可参考：MySQL 中如何归档数据
下面看看 pt-heartbeat 的具体方法。
（1）首先针对主库执行，定期更新主库的心跳表：
# pt-heartbeat -h 192.168.244.10 -u pt_user -p pt_pass --database percona --update --daemonize
指定的参数中：
注意，如果是第一次运行，还需指定 --create-table ，创建 heartbeat 表。
（2）其次针对从库执行，检查从库的主从延迟情况：
此时，需指定 --monitor 或者 --check。
其中，--monitor 是持续检测，每秒输出一次，如，
# pt-heartbeat -h 192.168.244.20 -u pt_user -p pt_pass --database percona --monitor
113.00s [ 1.88s, 0.38s, 0.13s ]
114.00s [ 3.78s, 0.76s, 0.25s ]
115.00s [ 5.70s, 1.14s, 0.38s ]
输出一共有 4 列，第 1 列是当前的延迟时间，第 2、第 3、第 4 列分别是最近 1 分钟、5 分钟和 15 分钟内的平均延迟情况。
也可指定 --check ，只检测一次，如，
# pt-heartbeat -h 192.168.244.20 -u pt_user -p pt_pass --database percona --check
303.00
pt-heartbeat 的实现原理
pt-heartbeat 首先会在主库上创建一张心跳表，并插入一条心跳记录。
mysql> show create table percona.heartbeat\G
*************************** 1. row ***************************
Table: heartbeat
Create Table: CREATE TABLE `heartbeat` (
`ts` varchar(26) NOT NULL,
`server_id` int unsigned NOT NULL,
`file` varchar(255) DEFAULT NULL,
`position` bigint unsigned DEFAULT NULL,
`relay_master_log_file` varchar(255) DEFAULT NULL,
`exec_master_log_pos` bigint unsigned DEFAULT NULL,
PRIMARY KEY (`server_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)
mysql> select * from percona.heartbeat;
+----------------------------+-----------+------------------+----------+-----------------------+---------------------+
| ts | server_id | file | position | relay_master_log_file | exec_master_log_pos |
+----------------------------+-----------+------------------+----------+-----------------------+---------------------+
| 2021-09-11T17:34:40.010430 | 1 | mysql-bin.000003 | 807269 | NULL | NULL |
+----------------------------+-----------+------------------+----------+-----------------------+---------------------+
1 row in set (0.00 sec)
在心跳表中，重点关注两列：ts 和 server_id，前者代表记录插入或更新时的系统时间，后者是主库的 server_id。
既然会存储实例的 server_id，就意味着这里的节点不一定是一级主库，也可以是级联复制中的中间节点。
随后，针对主库的 pt-heartbeat 会以每秒一次的频率更新这条记录，而针对从库的 pt-heartbeat 同样也会以每秒一次的固定频率进行检查。
两者的执行频率虽然一样（都是由 --interval 参数控制），但执行时间点却不同。
更新操作通常是整秒执行，如上面 ts 中的 40 秒，而 check 操作，则会滞后 0.5 秒（ 由 --skew 参数控制 ）执行。
主从延迟时间 = 系统当前时间 - 心跳表中的 ts 值 - skew。相关的源代码如下。
my ($ts, $hostname, $server_id) = $sth->fetchrow_array();
my $now = time;
PTDEBUG && _d("Heartbeat from server", $server_id, "\n",
" now:", ts($now, $utc), "\n",
" ts:", $ts, "\n",
"skew:", $skew);
my $delay = $now - unix_timestamp($ts, $utc) - $skew;
PTDEBUG && _d('Delay', sprintf('%.6f', $delay), 'on', $hostname);
$delay = 0.00 if $delay < 0;
无论是更新还是 check 操作，pt-heartbeat 都极度依赖于系统时间。
如果这两个操作是在不同主机上执行的，务必确保这两个主机的系统时间是一致的。
建议在同一台主机上执行这两个操作。
介绍完 pt-heartbeat ，接下来，看看 MySQL 8.0 原生的解决方案。
MySQL 8.0 原生的解决方案
MySQL 8.0 原生的解决方案主要是基于 performance_schema.replication_applier_status_by_worker 中的 APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP，这个字段记录了当前正在重放的事务在主库的提交时间。
看下面这个示例。
mysql> select * from performance_schema.replication_applier_status_by_worker\G
*************************** 1. row ***************************
CHANNEL_NAME:
WORKER_ID: 0
THREAD_ID: 3112
SERVICE_STATE: ON
LAST_ERROR_NUMBER: 0
LAST_ERROR_MESSAGE:
LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
LAST_APPLIED_TRANSACTION: bd6b3216-04d6-11ec-b76f-000c292c1f7b:2232
LAST_APPLIED_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2021-09-11 17:39:58.012221
LAST_APPLIED_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2021-09-11 17:39:58.012221
LAST_APPLIED_TRANSACTION_START_APPLY_TIMESTAMP: 2021-09-11 17:39:58.026871
LAST_APPLIED_TRANSACTION_END_APPLY_TIMESTAMP: 2021-09-11 17:39:58.029345
APPLYING_TRANSACTION: bd6b3216-04d6-11ec-b76f-000c292c1f7b:2233
APPLYING_TRANSACTION_ORIGINAL_COMMIT_TIMESTAMP: 2021-09-11 17:39:59.006270
APPLYING_TRANSACTION_IMMEDIATE_COMMIT_TIMESTAMP: 2021-09-11 17:39:59.006270
APPLYING_TRANSACTION_START_APPLY_TIMESTAMP: 2021-09-11 17:39:59.021139
LAST_APPLIED_TRANSACTION_RETRIES_COUNT: 0
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE:
LAST_APPLIED_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
APPLYING_TRANSACTION_RETRIES_COUNT: 0
APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_NUMBER: 0
APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_MESSAGE:
APPLYING_TRANSACTION_LAST_TRANSIENT_ERROR_TIMESTAMP: 0000-00-00 00:00:00.000000
1 row in set (0.00 sec)
所以，可通过以下 SQL 查看主从延迟情况。
select case
when min_commit_timestamp is null then 0
else unix_timestamp(now(6)) - unix_timestamp(min_commit_timestamp)
end as seconds_behind_master
from (
select min(applying_transaction_original_commit_timestamp) as min_commit_timestamp
from performance_schema.replication_applier_status_by_worker
where applying_transaction <> ''
) t;
注意，这个 SQL 同样也适用于多线程复制。
总结
Seconds_Behind_Master = 从库当前的系统时间 - SQL 线程当前重放的事务在主库的开始时间戳 - 主从之间的系统时间差。
在使用 Seconds_Behind_Master 时， 注意 Seconds_Behind_Master 的局限性。
Seconds_Behind_Master 只能衡量 SQL 线程的延迟情况，不能衡量 IO 线程的延迟情况。
对于 STATEMENT 格式和 ROW 格式的事务，Seconds_Behind_Master 的计算逻辑并不一样。具体来说，对于 STATEMENT 格式的事务，在计算 Seconds_Behind_Master 时，会减去 QUERY_EVENT 中的 exec_time。
不适用于级联复制场景。
虽然 Seconds_Behind_Master 有一定的局限性，但在绝大多数情况下，Seconds_Behind_Master 还是能很好的反映主从延迟情况。
在 MySQL 8.0 之前，业界用得比较多的主从延迟监控方案是 pt-heartbeat ，该工具是通过定期更新心跳记录来实现的。
在 MySQL 8.0 中，因为 binlog 中会记录事务在源主库（执行写操作的节点）提交的时间戳（original_commit_timestamp），所以我们可以直接使用 performance_schema 来计算主从延迟。
