问题

一段 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。

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

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