问题

一段 binlog 如上图，为什么这个 BEGIN 执行了 5 秒，是数据库卡了还是统计错了？

实验

先宽油做一个数据库：

为了实验方便，我们改一下 mysql 的提示符，将命令行的当前时间显示在上面，

将 binlog 格式改为 statement：

创建一个实验表：

跑一个事务：

解开对应的 binlog：

得到结果：

我们看到三组时间：

1. 黄色部分：

每个 binlog event 前都会带有一个时间戳，这个时间戳和我们执行每个语句时的开始时间对应（截图中会偶尔偏差 1s，是因为 SQL 是手工敲的，需要一些时间）

2. 红色部分：

exec_time，每个语句的 exec_time 与语句的执行时间对应，本例中是与 sleep 的时长对应，
而 BEGIN 语句的 exec_time 始终与第一个句子的执行时间相同，其原因是 BEGIN 是在第一个语句执行时，与第一个语句同时写入 binlog 的，这就引起了 exec_time 统计的偏差：BEGIN 的 exec_time 实际上是其后第一个语句的执行时间。

3. 每个语句前会有一个 SET TIMESTAMP，我们都知道其会影响语句中的时间函数，比如 now() 函数的时间基准。

我们重做一次实验，验证一下手工 SET TIMESTAMP 的影响：

如上图，我们改变了 timestamp。来看一下 binlog 的表现：

从图中可以看到：

1. binlog event 的时间戳随着 timestamp 变化，不再表示语句的实际开始时间，而是都置为设定的时间。

2. exec_time 计算出现了错误，不再表示实际的运行时间

由上面的实验，我们得到如下结论：

1. exec_time 是语句的运行时间。会受到 set timestamp 影响变得不准确

2. binlog event 的时间戳，是语句实际的开始时间。会受到 set timestamp 影响失去意义。

下期预告：

在慢日志，还有两个时间量：query_time 和 lock_time。

我们在下一期会介绍这几个量的意义和差异。

相关推荐：

第29问：MySQL 的复制心跳说它不想跳了

第28问：SIP 漂移时，会影响正在使用的数据库连接么？

第27问：information_schema.columns 表上做查询慢，为什么？

关于 MySQL 的技术内容，你们还有什么想知道的吗？赶紧留言告诉小编吧！