乐趣区

关于mysql:技术分享-关于-exectime-的深入研究

jiezi

作者：赵拂晓

爱可生 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

主库 exec_time 记录了 6s，略大于第一个 insert 语句的 5.04s，整个事务执行了 16s（15:57:00 开始，15:57:16 完结）。主库上的这个 exec_time 显然不能代表整个事务执行工夫了，那从库上呢？

  • 从库 binlog

从库 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

因为第一个 insert 语句中没有延时函数，执行了 0.03s，exec_time 记录了 0s（与第一个 SQL 工夫近似相等），而 select sleep()；不是事务 SQL，不会被记录到 binlog 中（select 放到 insert 后面执行，后果也是如此，感兴趣的敌人能够自行测试一下）。整个事务执行工夫为 10s（16:05:51 开始，16:06:01 完结），其中蕴含了 2 个 insert 语句和第一个 select 语句总的执行工夫。

  • 从库 binlog

这次从库 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

替换 insert 程序当前，begin 语句的 exec_time 与第一个 insert 语句的执行工夫统一，为 10s。整个事务执行了 15s（16:27:53 开始，16:28:08 完结）。exect_time 被记录了 3 次，别离为 10s、10s、5s。

  • 从库 binlog

从库没有批改 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

  • 从库 binlog

论断 2

  • binlog_format=statement 时，事务中的每个 DML 语句都会记录一个 exec_time（select 语句除外）
  • 主库 binlog 中的 exec_time 近似等于事务中第一个语句的执行工夫（与测试 1 论断统一）
  • 从库 binlog 中的 exec_time 近似等于整个事务的执行工夫（与测试 1 论断统一）

注意事项 2

  • RC 隔离级别下不容许应用 statement 格局的 binlog，否则会报错

原理剖析

  • 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 的值所匹配。

故障模拟

  • 此处应用 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）。

  • 从库开启了基于 LOGICAL_CLOCK 的并行复制（8 个 worker 线程）。

察看一会儿，从库复制提早始终为 0，在失常状况下，开启并行复制时根本不会有提早。

  • 用 iostat 察看磁盘 IO 状态，此时曾经有肯定的压力了，使用率 50% 左右，await 达到 4-5ms 左右。

  • 运行 stress，开始给磁盘减少压力。

  • 磁盘 IO 负载霎时就达到了瓶颈，使用率 100%，await 达到 350ms+。

  • 尽管曾经开启了并行复制，仍无奈防止地开始呈现提早（从库落后主库 6 秒）。

  • 解析从库 binlog 文件，察看到 exec_time 从 0 开始递增了。

  • 查看主从提早监控图，最高峰的时候达到了 8s 的提早，之后开始回落是因为 stress 把磁盘写满了，它的过程本人挂了。

  • 磁盘监控信息显示，在 15:36 的时候达到 iops 最高峰值 6.9k。

  • 间接在 binog 中过滤 exec_time=8，能够找到对应的值，能与 Seconds_Behind_Master 匹配上。

测试 2：模仿 CPU 瓶颈的场景

  • stress 加 4 个 CPU 负载

  • 此时磁盘使用率是失常的

  • CPU 的负载下来了，us% 达到 90%+ 的，load 达到 11 左右。

  • CPU 负载升高后，从库逐步开始呈现提早

  • 从主从提早监控图上看得更直观一些，提早是从 16:08 开始的。

  • binlog 中记录的工夫戳也是从 16:08 开始，从库回放事务时开始呈现沉积的景象。

  • CPU 使用率和 CPU 负载监控图比拟直观

  • 进行 stress 前再察看一下 Senconds_Behind_Master，曾经落后主库 17 秒了，并且这个值会越来越大。

在从库 binlog 中过滤 exec_time=17，也可能匹配到 Senconds_Behind_Master 的值。

测试 3：模仿网络提早的场景

  • 网络相干故障能够应用 tc 工具来实现，将从库网卡设置提早 500ms。

  • 从库很快地开始呈现提早。

  • 同样地，事务回放呈现沉积的景象。

  • 期待一段时间，察看到主从提早曾经超过 7 分钟。

  • 解析从库 binlog，过滤 exec_time=427，与 Seconds_Behind_Master 匹配。

  • 进行 tc 工具，复原网络提早。

  • 在 16:42 停掉 tc 后，从库上的网络流量突增，开始失常回放事务，直至追平主库。

总结

  • 从库 binlog 的 exec_time 在肯定水平上能够反映事务执行的快慢（row/statement），但并不一定齐全与主库事务执行工夫统一。
  • 如果呈现主库 exec_time=0，而从库 exec_time 始终在递增，此时很可能曾经呈现了主从提早，能够从服务器的资源负载方面着手排查，大概率是 CPU、磁盘、网络等呈现瓶颈所致。
  • 以上测试场景都是基于没有人为地去批改 timestamp 的状况，否则 exec_time 就没有参考意义了。

参考文档

https://www.percona.com/blog/…

https://mp.weixin.qq.com/s/TA…

退出移动版