技术分享 | 关于 exec_time 的深入研究
作者：赵黎明
爱可生 MySQL DBA 团队成员，熟悉 Oracle、MySQL 等数据库，擅长数据库性能问题诊断、事务与锁问题的分析等，负责处理客户 MySQL 及我司自研 DMP 平台日常运维中的问题，对开源数据库相关技术非常感兴趣。
本文来源：原创投稿
* 爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。
背景
什么是 exec_time
环境准备
测试 1（binlog_format=row）
结论 1
注意事项 1
测试 2（binlog_format=statement）
结论 2
注意事项 2
原理分析
故障案例
故障模拟
测试 1：模拟磁盘 IO 瓶颈的场景
测试 2：模拟 CPU 瓶颈的场景
测试 3：模拟网络延迟的场景
总结
参考文档
背景
最近在处理某客户的 MySQL 数据库主从延迟问题时，发现了一个与 exec_time 有关的奇怪现象，于是抽空做了一些测试，借此文分享一些心得。
什么是 exec_time
此处的 exec_time 是指 binlog 中记录的值，顾名思义，它是一个执行时间，那它是关于什么的呢？单个语句，整个事务，或是其他？我们先来做几个测试。
环境准备
- 环境信息
| 角色 | 主机/IP | 数据库版本 |
|---|---|---|
| 主库 | 10.186.60.62 | MySQL 5.7.32 |
| 从库 | 10.186.60.68 | MySQL 5.7.32 |
- 测试表
zlm@10.186.60.62 [zlm]> show create table t\G
*************************** 1. row ***************************
Table: t
Create Table: CREATE TABLE `t` (
`id` int(11) NOT NULL AUTO_INCREMENT,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8
1 row in set (0.00 sec)
zlm@10.186.60.62 [zlm]> select * from t;
Empty set (0.01 sec)
测试 1（binlog_format=row）
提交一个事务，其中包含 2 个 insert 语句（GTID=xxxx:1）
zlm@10.186.60.62 [zlm]> select @@binlog_format;
+-----------------+
| @@binlog_format |
+-----------------+
| ROW |
+-----------------+
1 row in set (0.00 sec)
zlm@10.186.60.62 [zlm]> begin;insert into t values(sleep(5));insert
into t values(sleep(10));commit;
Query OK, 0 rows affected (0.00 sec)
Query OK, 1 row affected (5.04 sec)
Query OK, 1 row affected (10.00 sec)
Query OK, 0 rows affected (0.00 sec)
zlm@10.186.60.62 [zlm]>
- 主库 binlog
image
image
主库 exec_time 记录了 6s，略大于第一个 insert 语句的 5.04s，整个事务执行了 16s（15:57:00 开始，15:57:16 结束）。主库上的这个 exec_time 显然不能代表整个事务执行时间了，那从库上呢？
- 从库 binlog
image
从库 exec_time 记录了 16s，与主库整个事务执行耗时“正好”相同，那我们能否用这个值来判断一个事务执行多久呢？
- 换一个写法，加 2 个 select 语句来延长事务提交时间（GTID=xxxx:2）
-- 这里模拟一个1064语法错误，让第2个select消耗的时间不被记录到事务中
zlm@10.186.60.62 [zlm]> begin;insert into t values(null);select
sleep(10);insert into t values(null);select sleep(5));commit;
Query OK, 0 rows affected (0.00 sec)
Query OK, 1 row affected (0.03 sec)
+-----------+
| sleep(10) |
+-----------+
| 0 |
+-----------+
1 row in set (10.01 sec)
Query OK, 1 row affected (0.00 sec)
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near ')' at line 1
Query OK, 0 rows affected (0.00 sec)
-- 事务中的第2个select语句执行失败并不影响整个事务的提交
zlm@10.186.60.62 [zlm]> select * from t;
+----+
| id |
+----+
| 1 |
| 2 |
| 3 |
| 4 |
+----+
4 rows in set (0.00 sec)
- 主库 binlog
image
image
由于第一个 insert 语句中没有延时函数，执行了 0.03s，exec_time 记录了 0s（与第一个 SQL 时间近似相等），而 select sleep()；不是事务 SQL，不会被记录到 binlog 中（select 放到 insert 前面执行，结果也是如此，感兴趣的朋友可以自行测试一下）。整个事务执行时间为 10s（16:05:51 开始，16:06:01 结束），其中包含了 2 个 insert 语句和第一个 select 语句总的执行时间。
- 从库 binlog
image
这次从库 binlog 中记录的 exec_time 少了 5s，为什么？因为主库执行整个事务耗时为 10s，第二个 select 消耗的 5s 并没有执行。这样看来，似乎从库 binlog 中 exec_time 记录的就是主库对应事务的执行时间？
结论 1
-
binlog_format=row 的情况下，对于同一个事务，exec_time 只记录一次。
-
主库 binlog 中的 exec_time 近似等于事务中第一个语句的执行时间（第一个 insert 执行了 5.04s，记录的是 6s；第二个 insert 执行了 0.03s，记录的是 0s，但不包括select）。
-
从库 binlog 中的 exec_time 近似等于整个事务的执行时间（事务 2 的第二个 select 的 5s 没有被记录到事务中）。
注意事项 1
- 如果要在 binlog 中记录完整 SQL，在 row 模式下，需要主库设置参数 binlog_rows_query_log_events=1，建议开启该参数，有助于在故障排查时能快速找到相关业务 SQL，从而能定位到具体的功能模块，做进一步的故障分析。
测试 2（binlog_format=statement）
- 提交一个事务，其中包含2个insert语句（insert语句位置互换，GTID=xxxx:3）
zlm@10.186.60.62 [zlm]> set @@session.binlog_format=statement;
Query OK, 0 rows affected (0.00 sec)
zlm@10.186.60.62 [zlm]> select @@session.binlog_format;
+-------------------------+
| @@session.binlog_format |
+-------------------------+
| STATEMENT |
+-------------------------+
1 row in set (0.00 sec)
zlm@10.186.60.62 [zlm]> begin;insert into t values(sleep(10));insert into t values(sleep(5));commit;
Query OK, 0 rows affected (0.00 sec)
Query OK, 1 row affected, 1 warning (10.01 sec)
Query OK, 1 row affected, 1 warning (5.01 sec)
Query OK, 0 rows affected (0.00 sec)
zlm@10.186.60.62 [zlm]>
- 主库 binlog
image
交换 insert 顺序以后，begin 语句的 exec_time 与第一个 insert 语句的执行时间一致，为 10s。整个事务执行了 15s（16:27:53 开始，16:28:08 结束）。exect_time 被记录了 3 次，分别为 10s、10s、5s。
- 从库 binlog
image
image
从库没有修改 binlog_format，仍然是 row 格式，其中的 exec_time 记录了 25s。整个事务执行时间为 15s（16:27:53 开始，16:28:08 结束），exec_time 记录的值比事务执行时间多了 10s，似乎是把 begin 的 10s 又算了一次？
- 换一个写法，加 2 个 select 语句来延长事务提交时间（select语句位置互换，GTID=xxxx:4）
zlm@10.186.60.62 [zlm]> begin;insert into t values(null);select sleep(5);insert into t values(null);select sleep(10);commit;
Query OK, 0 rows affected (0.00 sec)
Query OK, 1 row affected (0.02 sec)
+----------+
| sleep(5) |
+----------+
| 0 |
+----------+
1 row in set (5.00 sec)
Query OK, 1 row affected (0.00 sec)
+-----------+
| sleep(10) |
+-----------+
| 0 |
+-----------+
1 row in set (10.00 sec)
Query OK, 0 rows affected (0.00 sec)
- 主库 binlog
image
- 从库 binlog
image
结论 2
-
binlog_format=statement 时，事务中的每个 DML 语句都会记录一个 exec_time（select 语句除外）
-
主库 binlog 中的 exec_time 近似等于事务中第一个语句的执行时间（与测试 1 结论一致）
-
从库 binlog 中的 exec_time 近似等于整个事务的执行时间（与测试 1 结论一致）
注意事项 2
- RC 隔离级别下不允许使用 statement 格式的 binlog，否则会报错
image
原理分析
-
binlog 中 exec_time 的值表示事务开始执行的时间戳到事务执行结束的时间戳之间的差值(unixtime)，如果事务中只有一个 SQL 语句（在跑批的情况下，一个事务通常包含多个 SQL），可近似看作一个事务在主库上的执行时间，单位为秒。
-
事务一旦在主库上提交后，就会在 binlog 中写入事务结束时间戳，随后将其传递到从库并形成 relay log，此时 relay log 中记录的事务起始时间戳与主库 binlog 中的值是一致的。
-
从库要追上主库的事务，就需要去不停地回放接收到的 relay log，并生成自己的 binlog，但要注意的是，由从库自己生成的 binlog 中记录的事务起始时间戳仍然与主库的一致，而结束时间戳是在事务回放完成后才记录的，因此这个 exec_time 在从库上就不能视为从库执行 SQL 消耗的时间，而一定是大于这个值的（除了主库执行的
时间，还要考虑主库 binlog 落盘的时间、网络传输 binlog 的时间、从库读取 relay log 的时间等，然后才是从库自己的执行时间)。
故障案例
经过之前的测试，我们已经对 exec_time 有了进一步的认识，下面回到文章开头提到的那个奇怪的现象，先来看下故障当时抓到的现场截图，某实例在凌晨 5 点的时候，出现主从延迟超过 1000 多秒的告警。
image
基于之前的测试，我们可能会认为，从库上每个事务执行了 1000 多秒，难道是故障时刻有某个大事务或是在没有主键/唯一键上的表上做操作导致？
解析多个 binlog 后，发现一个奇怪的现象，从 5 点开始，exec_time 的值出现了线性递增的现象，直至增长到了 1000 多秒触发了主从延迟的告警。
image
其实，exec_time 并不能简单视为从库执行事务消耗的时间，还要考虑其他因素（CPU、磁盘、网络等），但这个指标能在一定程度上用于判断主从延迟，它基本与实时的 Seconds_Behind_Master 的值所匹配。
故障模拟
- 此处使用 stress 工具来实现，它是一款 linux 工具，主要用于模拟系统负载较高的场景（CPU、磁盘、内存等）。
-- 查看帮助信息
03:35 PM dmp2 (master) ~# stress --help
`stress' imposes certain types of compute stress on your system
Usage: stress [OPTION [ARG]] ...
-?, --help show this help statement
--version show version statement
-v, --verbose be verbose
-q, --quiet be quiet
-n, --dry-run show what would have been done
-t, --timeout N timeout after N seconds
--backoff N wait factor of N microseconds before work starts
-c, --cpu N spawn N workers spinning on sqrt()
-i, --io N spawn N workers spinning on sync()
-m, --vm N spawn N workers spinning on malloc()/free()
--vm-bytes B malloc B bytes per vm worker (default is 256MB)
--vm-stride B touch a byte every B bytes (default is 4096)
--vm-hang N sleep N secs before free (default none, 0 is inf)
--vm-keep redirty memory instead of freeing and reallocating
-d, --hdd N spawn N workers spinning on write()/unlink()
--hdd-bytes B write B bytes per hdd worker (default is 1GB)
Example: stress --cpu 8 --io 4 --vm 2 --vm-bytes 128M --timeout 10s
Note: Numbers may be suffixed with s,m,h,d,y (time) or B,K,M,G (size).
测试 1：模拟磁盘 IO 瓶颈的场景
用 sysbench 给主库施加点压力（使用 oltp_read_write.lua 脚本，每个事务仅含一条简单 DML）。
image
- 从库开启了基于 LOGICAL_CLOCK 的并行复制（8 个 worker 线程）。
image
观察一会儿，从库复制延迟始终为 0，在正常情况下，开启并行复制时基本不会有延迟。
image
- 用 iostat 观察磁盘 IO 状态，此时已经有一定的压力了，使用率 50% 左右，await 达到 4-5ms 左右。
image
- 运行 stress，开始给磁盘增加压力。
image
- 磁盘 IO 负载瞬间就达到了瓶颈，使用率 100%，await 达到 350ms+。
image
- 虽然已经开启了并行复制，仍无法避免地开始出现延迟（从库落后主库 6 秒）。
image
- 解析从库 binlog 文件，观察到 exec_time 从 0 开始递增了。
image
- 查看主从延迟监控图，最高峰的时候达到了 8s 的延迟，之后开始回落是因为 stress 把磁盘写满了，它的进程自己挂了。
image
image
- 磁盘监控信息显示，在 15:36 的时候达到 iops 最高峰值 6.9k。
image
- 直接在 binog 中过滤 exec_time=8，可以找到对应的值，能与 Seconds_Behind_Master 匹配上。
image
测试 2：模拟 CPU 瓶颈的场景
- stress 加 4 个 CPU 负载
image
- 此时磁盘使用率是正常的
image
- CPU 的负载上去了，us% 达到 90%+ 的，load 达到 11 左右。
image
- CPU 负载升高后，从库逐渐开始出现延迟
image
- 从主从延迟监控图上看得更直观一些，延迟是从 16:08 开始的。
image
- binlog 中记录的时间戳也是从 16:08 开始，从库回放事务时开始出现堆积的现象。
image
- CPU 使用率和 CPU 负载监控图比较直观
image
image
- 停止 stress 前再观察一下 Senconds_Behind_Master，已经落后主库 17 秒了，并且这个值会越来越大。
image
在从库 binlog 中过滤 exec_time=17，也能够匹配到 Senconds_Behind_Master 的值。
image
测试 3：模拟网络延迟的场景
- 网络相关故障可以使用 tc 工具来实现，将从库网卡设置延迟 500ms。
image
- 从库很快地开始出现延迟。
image
- 同样地，事务回放出现堆积的现象。
image
- 等待一段时间，观察到主从延迟已经超过 7 分钟。
image
- 解析从库 binlog，过滤 exec_time=427，与 Seconds_Behind_Master 匹配。
image
- 停止 tc 工具，恢复网络延迟。
image
- 在 16:42 停掉 tc 后，从库上的网络流量突增，开始正常回放事务，直至追平主库。
image
总结
-
从库 binlog 的 exec_time 在一定程度上可以反映事务执行的快慢（row/statement），但并不一定完全与主库事务执行时间一致。
-
如果出现主库 exec_time=0，而从库 exec_time 一直在递增，此时很可能已经出现了主从延迟，可以从服务器的资源负载方面着手排查，大概率是 CPU、磁盘、网络等出现瓶颈所致。
-
以上测试场景都是基于没有人为地去修改 timestamp 的情况，否则 exec_time 就没有参考意义了。
参考文档
https://www.percona.com/blog/2011/01/31/what-is-exec_time-in-binary-logs/
