背景 什么是 exec_time 环境准备
测试 1(binlog_format=row) 结论 1 注意事项 1 测试 2(binlog_format=statement) 结论 2 注意事项 2 原理分析 故障案例 故障模拟
测试 1:模拟磁盘 IO 瓶颈的场景 测试 2:模拟 CPU 瓶颈的场景 测试 3:模拟网络延迟的场景 总结 参考文档
最近在处理某客户的 MySQL 数据库主从延迟问题时,发现了一个与 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)
提交一个事务,其中包含 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]>
主库 exec_time 记录了 6s,略大于第一个 insert 语句的 5.04s,整个事务执行了 16s(15:57:00 开始,15:57:16 结束)。主库上的这个 exec_time 显然不能代表整个事务执行时间了,那从库上呢?
从库 exec_time 记录了 16s,与主库整个事务执行耗时“正好”相同,那我们能否用这个值来判断一个事务执行多久呢?
-- 这里模拟一个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)
由于第一个 insert 语句中没有延时函数,执行了 0.03s,exec_time 记录了 0s(与第一个 SQL 时间近似相等),而 select sleep();不是事务 SQL,不会被记录到 binlog 中(select 放到 insert 前面执行,结果也是如此,感兴趣的朋友可以自行测试一下)。整个事务执行时间为 10s(16:05:51 开始,16:06:01 结束),其中包含了 2 个 insert 语句和第一个 select 语句总的执行时间。
这次从库 binlog 中记录的 exec_time 少了 5s,为什么?因为主库执行整个事务耗时为 10s,第二个 select 消耗的 5s 并没有执行。这样看来,似乎从库 binlog 中 exec_time 记录的就是主库对应事务的执行时间?
binlog_format=row 的情况下,对于同一个事务,exec_time 只记录一次。
主库 binlog 中的 exec_time 近似等于事务中第一个语句的执行时间(第一个 insert 执行了 5.04s,记录的是 6s;第二个 insert 执行了 0.03s,记录的是 0s,但不包括select)。
从库 binlog 中的 exec_time 近似等于整个事务的执行时间(事务 2 的第二个 select 的 5s 没有被记录到事务中)。
- 提交一个事务,其中包含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]>
交换 insert 顺序以后,begin 语句的 exec_time 与第一个 insert 语句的执行时间一致,为 10s。整个事务执行了 15s(16:27:53 开始,16:28:08 结束)。exect_time 被记录了 3 次,分别为 10s、10s、5s。
从库没有修改 binlog_format,仍然是 row 格式,其中的 exec_time 记录了 25s。整个事务执行时间为 15s(16:27:53 开始,16:28:08 结束),exec_time 记录的值比事务执行时间多了 10s,似乎是把 begin 的 10s 又算了一次?
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_format=statement 时,事务中的每个 DML 语句都会记录一个 exec_time(select 语句除外)
主库 binlog 中的 exec_time 近似等于事务中第一个语句的执行时间(与测试 1 结论一致)
从库 binlog 中的 exec_time 近似等于整个事务的执行时间(与测试 1 结论一致)
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 多秒的告警。
基于之前的测试,我们可能会认为,从库上每个事务执行了 1000 多秒,难道是故障时刻有某个大事务或是在没有主键/唯一键上的表上做操作导致?
解析多个 binlog 后,发现从 5 点开始,exec_time 的值出现了线性递增的现象,直至增长到了 1000 多秒触发了主从延迟的告警。
其实,exec_time 并不能简单视为从库执行事务消耗的时间,还要考虑其他因素(CPU、磁盘、网络等),但这个指标能在一定程度上用于判断主从延迟,它基本与实时的 Seconds_Behind_Master 的值所匹配。
-- 查看帮助信息
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).
用 sysbench 给主库施加点压力(使用 oltp_read_write.lua 脚本,每个事务仅含一条简单 DML)。
观察一会儿,从库复制延迟始终为 0,在正常情况下,开启并行复制时基本不会有延迟。
在从库 binlog 中过滤 exec_time=17,也能够匹配到 Senconds_Behind_Master 的值。
从库 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/
https://mp.weixin.qq.com/s/TAf4yCC1g_xrvEq2BHJINQ
文章推荐:
技术分享 | 如何优雅地在 Windows 上从 MySQL 5.6 升级到 5.7
社区近期动态