- 当前位置：首页 >系统运维 >MySQL binlog 中的时间戳，你明白了吗？
MySQL binlog 中的时间戳，你明白了吗？
发布时间：2025-11-05 06:53:38 来源：技术快报 作者：IT科技
引言
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 headertimestamp，保存语句开始执行的时间，正是本文重点关注的字段；
type_code，保存 Event 的WordPress模板类型；
server_id，保存生成 Event 的数据库的 server_id；
event_len，保存整个 Event 的长度；
end_log_p，保存下一个 Event 的开始位置；
Event data，不同 type_code 对应不同的格式；Event footercrc，保存整个 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 中，不会实际执行。显式事务 复制08:32:05> begin; Query OK, 0 rows affected (0.00 sec) 08: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 08:32:45> commit; Query OK, 0 rows affected (0.21 sec)1.2.3.4.5.6.7.8.9.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 乱序。
复制8:32:46 GTID 8:32:16 Query 8:32:16 Rows_query 8:32:46 XID1.2.3.4.其中：
不同于隐式事务，显式事务中执行 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 语句。显式事务 复制19:16:49> begin; Query OK, 0 rows affected (0.00 sec) 19: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 19:17:19> commit; Query OK, 0 rows affected (0.01 sec)1.2.3.4.5.6.7.8.9.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 要晚，因此主从延迟会出现跳点，显示本不会出现的延迟。具体将在下一篇文章中讲解。
源码下载服务器租用益华科技IT技术网亿华云企商汇源码库香港云服务器IT资讯网益强编程堂益强科技汇智坊思维库亿华科技益强智未来益强智囊团益强编程舍亿华灵动亿华智慧云云站无忧亿华互联益强IT技术网创站工坊码力社编程之道码上建站益华IT技术论坛亿华云计算科技前瞻极客编程智能时代益强资讯优选益华科技IT资讯网运维纵横益强数据堂亿华云云智核多维IT资讯全栈开发益强前沿资讯
- Copyright © 2025 Powered by MySQL binlog 中的时间戳，你明白了吗？,技术快报 滇ICP备2023006006号-46sitemap