技术分享 | 关于 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

主库 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 v