MySQL binlog 中的时间戳，你明白了吗？-51CTO.COM

引言

MySQL 中的主从复制基于逻辑日志 binlog 实现，而 binlog 由多个 event 组成。每个 event 自带时间戳，而主从延迟的计算正是基于该时间戳实现，因此 event 的时间戳很重要。本文测试并分析 binlog 不同模式下时间戳的区别。

概念

binlog_format

MySQL 中 binlog 有三种模式，包括：

statement-based logging（语句模式），记录原始 SQL，缺点是可能导致数据不一致；
row-based logging（行模式），对于 DML，记录每一行数据的变化，对于 DDL，记录原始 SQL，也是默认值；
mixed logging（混合模式），优先使用语句模式，不满足条件时切换为行模式，常见的不满足条件的场景包括：

使用非确定性函数或语句，比如 UUID()、NOW()；

操作包含触发器、存储过程或用户定义函数（UDF）。

需要注意的是可以设置的 binog 模式与事务隔离级别有关系。

If you are using InnoDB tables and the transaction isolation level is READ COMMITTED or READ UNCOMMITTED, only row-based logging can be used.

其中：

READ COMMITTED 与 READ UNCOMMITTED 中仅支持行模式，可以修改为语句模式，但执行 SQL 时会报错。
不支持的原因是语句模式下这两种事务隔离级别可能导致数据不一致。

参考文章为什么 MySQL 事务默认隔离级别是可重复读？，其中假设两个事务的执行顺序见下表。

时间	事务 A	事务 B
1	begin;	begin;
2	delete from A where a < 10;
3		insert into A values(5);
4		commit;
5	commit;

binlog 中的记录顺序如下所示。

图片

显然，事务的执行顺序与提交顺序不同，而 binlog 中的记录顺序与事务的提交顺序相同，因此导致主从事务的执行顺序不同，从而出现数据不一致。

Event

本节参考《深入理解 MySQL 主从原理》。

每个事务的 binlog 由多个 Event 组成，每个 Event 的主要结构包括：

Event header

timestamp，保存语句开始执行的时间，正是本文重点关注的字段；

type_code，保存 Event 的类型；

server_id，保存生成 Event 的数据库的 server_id；

event_len，保存整个 Event 的长度；

end_log_p，保存下一个 Event 的开始位置；

Event data，不同 type_code 对应不同的格式；
Event footer
crc，保存整个 Event 的 crc 校验码，用于标识 Event 的完整性。

如下所示，是语句模式下一段 binlog Event，其中红框中都是 Event header。

图片

常见的 Event 类型按照写入文件的顺序包括：

GTID_EVENT，其中携带 last commit 和 seq number 等信息；
QUERY_EVENT，语句模式下记录实际的语句，行模式下 DML 不记录实际的语句，DDL 是记录的语句；
TABLE_MAP_EVENT，包含 table_id 和具体表名的映射关系；
WRITE_ROWS_EVENT，INSERT 语句生成的 Event，包括插入的实际数据，行模式中特有；
DELETE_ROWS_EVENT，DELETE 语句生成的 Event，包括实际要删除的数据，行模式中特有；
UPDATE_ROWS_EVENT，UPDTE 语句生成的 Event，包括更新前后的数据，行模式中特有；
XID_EVENT，其中携带 XID 信息。

测试

测试环境

数据库版本：5.7.24

事务隔离级别：RR

开始测试前指定提示符 prompt，从而将命令行的当前时间显示在前面。

/export/servers/mysql/bin/mysql -uadmin -p3341 -h 127.0.0.1 -P 3341 -D test_zk --prompt='\r:\m:\s> '1.

注意显示的时间与命令开始执行的时间会有偏差，原因是输入命令需要时间，而显示的时间是输入命令的开始时间。

下面分别测试行模式与语句模式下隐式事务与显式事务写入 binlog 的区别。

行模式

隐式事务

08:27:31> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.81 sec)
Rows matched: 999989  Changed: 999989  Warnings: 01.
2.
3.

查看 binlog；

# at 194
#240813  8:27:32 server id 3341  end_log_pos 259 CRC32 0x8f3d5b01       GTID    last_committed=0        sequence_number=1       rbr_notallow=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67636'/*!*/;
# at 259
#240813  8:27:32 server id 3341  end_log_pos 342 CRC32 0x83532332       Query   thread_id=1250  exec_time=0     error_code=0
SET TIMESTAMP=1723508852/*!*/;
BEGIN
/*!*/;
# at 342
#240813  8:27:32 server id 3341  end_log_pos 418 CRC32 0xde6a90cd       Rows_query
# update t3_bak set create_time=now() where id<1000000
# at 418
#240813  8:27:32 server id 3341  end_log_pos 477 CRC32 0x3c9742c6       Table_map: `test_zk`.`t3_bak` mapped to number 2270
# at 477
#240813  8:27:32 server id 3341  end_log_pos 8649 CRC32 0x0a5f2233      Update_rows: table id 2270
# at 8649
#240813  8:27:32 server id 3341  end_log_pos 16825 CRC32 0x4a036014     Update_rows: table id 2270
...
# at 44194605
#240813  8:27:32 server id 3341  end_log_pos 44194636 CRC32 0xd524e4c2  Xid = 1520760
COMMIT/*!*/;1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.

其中：

update 开始时间 08:27:32，执行用时 8.81 s，因此结束时间 08:27:40；
所有 event header timestamp 相同，均显示 8:27:32，等于 update 的开始时间；
query event 显示 exec_time=0；
SET TIMESTAMP=1723509136，用于保证主从执行环境一致；
行模式 binlog 中 Rows_query 记录原始 SQL 的原因是开启 binlog_rows_query_log_events 参数，用于将原始 SQL 作为注释保存在 binlog 中，不会实际执行。

显式事务

32:05> begin;
Query OK, 0 rows affected (0.00 sec)

32:15> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.68 sec)
Rows matched: 999989  Changed: 999989  Warnings: 0

32:45> commit;
Query OK, 0 rows affected (0.21 sec)1.









binlog：

# at 194
#240813  8:32:46 server id 3341  end_log_pos 259 CRC32 0xd3661504       GTID    last_committed=0        sequence_number=1       rbr_notallow=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67637'/*!*/;
# at 259
#240813  8:32:16 server id 3341  end_log_pos 342 CRC32 0x99dba315       Query   thread_id=1250  exec_time=0     error_code=0
SET TIMESTAMP=1723509136/*!*/;
BEGIN
/*!*/;
# at 342
#240813  8:32:16 server id 3341  end_log_pos 418 CRC32 0x9138a9a5       Rows_query
# update t3_bak set create_time=now() where id<1000000
...
# at 44194605
#240813  8:32:46 server id 3341  end_log_pos 44194636 CRC32 0x892dfbf1  Xid = 1520766
COMMIT/*!*/;1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.

其中：

update 开始时间 08:27:31，执行用时 8.81 s，因此结束时间 08:27:40；
GTID_event 与 XID_EVENT 的 timestamp 相同，等于 8:32:46，等于 commit 的开始执行时间；
Query event 与 Rows_query event 的 timestamp 相同，等于 8:32:16，等于 update 的开始执行时间；
begin 的 timestamp 等于 update 的开始时间，并不等于实际 begin 语句的实际实际执行时间，可以简单认为 binlog 中的 BEGIN 与实际的 begin 命令无关；
显然 binlog 中没有保存执行 begin 命令的时间，当然执行 begin 语句以后执行具体 SQL 以前并没有启动事务。具体可以参考文章 MySQL 核心模块揭秘 | 04 期 | 终于要启动事务了；
query event 显示 exec_time=0。

分析

到这里，可以提出以下三个问题：

为什么隐式事务中所有 event timestamp 等于 update 的开始时间，包括 XID_EVENT；
为什么显式事务中 event timestamp 乱序；
为什么隐式事务与显式事务中 query event 均显示 exec_time=0。

下面分析原因。

首先是第一个问题，为什么隐式事务中所有 event timestamp 等于 update 的开始时间，包括 XID_EVENT。

原因是每条命令执行前获取时间戳，通过函数 thd->set_time() 获取，而这条语句生成的多个 event 的时间戳从语句继承过来。

隐式事务中必然仅执行一条 SQL，因此所有 event timestamp 等于 update 的开始时间。

然后是第二个问题，为什么显式事务中 event timestamp 乱序。

32:46 GTID
32:16 Query
32:16 Rows_query
32:46 XID1.




其中：

不同于隐式事务，显式事务中执行 commit 命令，执行前同样执行函数 thd->set_time()，从而影响到自己生成的 binlog event；
GTID_event 与 XID_EVENT 都是 commit 命令在事务提交阶段生成的 Event，因此显示 commit 的开始执行时间；
显然 GTID_event 生成的晚但是写入 binlog 文件早，原因是 GTID_event 是在事务提交阶段中创建后直接写入文件，没有经过 binlog cache；
GTID_event 始终是事务的第一个 event，原因是 binlog 中需要提前知道 GTID 的具体信息，因此在提交时将其组装在最前面。

最后是第三个问题，为什么隐式事务与显式事务中 query event 均显示 exec_time=0。

原因是：

QUERY_EVENT 中的 exec_time 只记录更改第一条数据的执行用时，且一般看到的都是 begin 语句；
begin 的 exec_time 等于其后更改第一条数据的执行用时，原因是 begin 是在更改第一条数据后，写入 binlog；
因此如果更改第一条数据的执行用时很短，就会显示为 query event 中的 exec_time=0。当然假如 SQL 中包括 sleep，显示 exec_time 不等于 0。

因此，对于行模式：

无法获取到 SQL 的执行用时；
显式事务的 Rows_query 与隐式事务的全部 event timestamp 等于 SQL 的开始执行时间。

可以得出以下两点结论：

对于大事务，每条 SQL 计算主从延迟时由于 event timestamp 相同，从库执行完成前主从延迟都将持续增加（对于单线程复制）；
对于长事务，GTID_event 与 XID_EVENT 比中间 event timestamp 要晚，因此主从延迟会出现跳点，显示本不会出现的延迟。

语句模式

修改 binlog 模式；

set session binlog_format='statement';1.

隐式事务

18:12:31> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.19 sec)
Rows matched: 999989  Changed: 999989  Warnings: 01.
2.
3.

binlog；

# at 194
#240816 18:12:32 server id 3341  end_log_pos 259 CRC32 0x47293428       GTID    last_committed=0        sequence_number=1       rbr_notallow=no
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67648'/*!*/;
# at 259
#240816 18:12:32 server id 3341  end_log_pos 352 CRC32 0xf5dd67f7       Query   thread_id=1261  exec_time=8     error_code=0
BEGIN
/*!*/;
# at 352
#240816 18:12:32 server id 3341  end_log_pos 492 CRC32 0xc5d67750       Query   thread_id=1261  exec_time=8     error_code=0
use `test_zk`/*!*/;
SET TIMESTAMP=1723803152/*!*/;
update t3_bak set create_time=now() where id<1000000
/*!*/;
# at 492
#240816 18:12:32 server id 3341  end_log_pos 523 CRC32 0xe90b07a7       Xid = 1521788
COMMIT/*!*/;1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.

其中：

update 开始时间 18:12:32，执行用时 8.19 s，因此结束时间 18:12:40；
所有 event timestamp 相同，均显示 18:12:32，等于 update 的开始时间；
query event 显示 exec_time=8，等于 BEGIN 后第一条语句的执行用时；
语句模式中事务中的每个 DML 语句都会记录一个 exec_time。

查看 event，可以更清楚的看到事务的全部 event。

18:25:39> show binlog events in 'mysql-bin.000080';
+------------------+-----+----------------+-----------+-------------+-----------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                                  |
+------------------+-----+----------------+-----------+-------------+-----------------------------------------------------------------------+
| mysql-bin.000080 |   4 | Format_desc    |      3341 |         123 | Server ver: 5.7.24-log, Binlog ver: 4                                 |
| mysql-bin.000080 | 123 | Previous_gtids |      3341 |         194 | d16716c7-c94e-11ed-a186-fa163e19c3b7:1-67647                          |
| mysql-bin.000080 | 194 | Gtid           |      3341 |         259 | SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67648' |
| mysql-bin.000080 | 259 | Query          |      3341 |         352 | BEGIN                                                                 |
| mysql-bin.000080 | 352 | Query          |      3341 |         492 | use `test_zk`; update t3_bak set create_time=now() where id<1000000   |
| mysql-bin.000080 | 492 | Xid            |      3341 |         523 | COMMIT /* xid=1521788 */                                              |
+------------------+-----+----------------+-----------+-------------+-----------------------------------------------------------------------+
6 rows in set (0.00 sec)1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.

其中：

QUERY_EVENT 中显示 info = BEGIN，可以简单理解为自动加 BEGIN 语句。

显式事务

16:49> begin;
Query OK, 0 rows affected (0.00 sec)

16:54> update t3_bak set create_time=now() where id<1000000;
Query OK, 999989 rows affected (8.47 sec)
Rows matched: 999989  Changed: 999989  Warnings: 0

17:19> commit;
Query OK, 0 rows affected (0.01 sec)1.









binlog；

# at 194
#240816 19:17:19 server id 3341  end_log_pos 259 CRC32 0x364ff2e2       GTID    last_committed=0        sequence_number=1       rbr_notallow=no
SET @@SESSION.GTID_NEXT= 'd16716c7-c94e-11ed-a186-fa163e19c3b7:67649'/*!*/;
# at 259
#240816 19:16:54 server id 3341  end_log_pos 352 CRC32 0x368c08f4       Query   thread_id=1261  exec_time=8     error_code=0
BEGIN
/*!*/;
# at 352
#240816 19:16:54 server id 3341  end_log_pos 492 CRC32 0x0450bba8       Query   thread_id=1261  exec_time=8     error_code=0
use `test_zk`/*!*/;
SET TIMESTAMP=1723807014/*!*/;
update t3_bak set create_time=now() where id<1000000
/*!*/;
# at 492
#240816 19:17:19 server id 3341  end_log_pos 523 CRC32 0xf75171f9       Xid = 1521794
COMMIT/*!*/;1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.

其中：

update 开始时间 19:16:54，执行用时 8.47 s，因此结束时间 19:17:02；
GTID_event 与 XID_EVENT timestamp 相同，等于 19:17:19，等于 commit 的开始执行时间；
Query event 与 Rows_query event timestamp 相同，等于 19:16:54，等于 update 的开始执行时间；
BEGIN timestamp 等于 update 的开始时间，并不等于实际 begin 语句的实际实际执行时间；
query event 显示 exec_time=8，等于 BEGIN 后第一条语句的执行用时。

对比

类型	exec_time	所有 event timestamp 相同
行模式 + 隐式事务	通常等于 0	是
行模式 + 显式事务	通常等于 0	否
语句模式 + 隐式事务	等于事务中第一条 SQL 的执行用时	是
语句模式 + 显式事务	等于事务中第一条 SQL 的执行用时	否

其中：

行模式中 QUERY_EVENT 中的 exec_time 通常等于 0，因此可以认为无效；
语句模式中 QUERY_EVENT 中的 exec_time 等于事务中第一条 SQL 的执行用时；
显式事务中 commit 是单独的命令，执行前获取时间戳，因此与事务中其他 event 的时间戳不同。

结论

本文主要测试并介绍 binlog event header 的 timestamp 字段与 QUERY_EVENT 中的 exec_time 字段。

binlog event header 的 timestamp 字段中保存语句开始执行的时间，具体取值与是否使用显式事务有关：

隐式事务，所有 event header timestamp 相同，均等于语句的开始执行时间；
显式事务，GTID_event 与 XID_EVENT 的 timestamp 与其他 event 不同，原因是单独执行 commit 命令时重新获取时间戳。

QUERY_EVENT 中的 exec_time 字段中保存更改第一条数据的执行用时，具体取值与 binlog 的模式有关：

行模式，通常等于 0，原因是理论上更改一条数据很快；
语句模式，通常不等于 0，原因是等于 SQL 的执行用时（可能更新多行），且每个 DML 语句都会记录一个 exec_time。

因此，对于行模式：

无法获取到 SQL 的执行用时；
无法获取到显式事务中 begin 的执行时间。

此外可以发现 timestamp 对于大事务与长事务主从延迟的影响：

对于大事务，每条 SQL 计算主从延迟时由于 event timestamp 相同，从库执行完成前主从延迟都将持续增加（对于单线程复制）；
对于长事务，GTID_event 与 XID_EVENT 比中间 event timestamp 要晚，因此主从延迟会出现跳点，显示本不会出现的延迟。

具体将在下一篇文章中讲解。