Binlog timestamp是语句开始时的thd->start_time,易被SET TIMESTAMP覆盖而失真;exec_time受同一机制影响且逻辑缺陷(如BEGIN取后续语句耗时);真正可靠的是original_commit_timestamp——主库提交时刻的微秒级UTC时间戳,不受人为设置干扰。

Binlog 的 timestamp 不是“执行完成时间”,而是语句开始时的 thd->start_time,且极易被 SET TIMESTAMP 覆盖 —— 所以它常不准,不能用于判断真实耗时或事务顺序。
Binlog timestamp 来源就是 THD::start_time
每个 binlog event 在构造时,直接从当前线程(THD)取 start_time 填入 header 的 when 字段。而这个 start_time 并非固定为系统当前时间:
- 若未显式设置,它等于语句进入执行前调用
THD::set_time()时的time(0) - 若 SQL 中出现
SET TIMESTAMP=1234567890,则后续所有语句的start_time都会被强制设为该值,binlog timestamp 也同步变为此值 - 在 ROW 格式下,
Rows_log_event回放时也会调用set_time()把 event header 的 timestamp 写回thd->start_time,进一步污染上下文
exec_time 字段为什么也靠不住
exec_time 表示的是语句“从开始执行到写入 binlog 的耗时”,但它同样受 SET TIMESTAMP 影响,且逻辑有硬伤:
-
BEGIN语句自身不执行,它的exec_time实际取自其后第一条 DML 的执行时间,纯属拼接结果 - 当
SET TIMESTAMP被设置后,MySQL 内部会用该值重置thd->start_time,导致后续语句的exec_time = time(0) - thd->start_time计算失真 - 大事务中,如果中间某条语句卡住(如锁等待),
exec_time会累积整个阻塞时间,而非单条语句真实执行时间
时间乱序不是 bug,是设计使然
binlog 时间戳只反映“语句启动瞬间”,不保证按提交顺序排列。以下情况必然导致乱序:
- 长事务 A 启动早、执行久(比如
SLEEP(30)),其 binlog timestamp 是 t0;短事务 B 在 t0+5s 启动、1s 完成,timestamp 是 t0+5 —— 但 B 的 event 可能先写入 binlog,位置在 A 前面 - 主库开启
binlog_format=MIXED或STATEMENT时,函数类语句(NOW(),SYSDATE())行为依赖SET TIMESTAMP,进一步放大时间偏差 - 从库回放时,
SET TIMESTAMP会被还原,但 relay log 中的 timestamp 已固化,造成主从看到的“同一事件时间”不一致
真正可用的时间字段只有 original_commit_timestamp
MySQL 5.7.20+ 引入了基于 GTID 的高精度时间戳字段,比传统 timestamp 可靠得多:
-
original_commit_timestamp:主库事务实际提交时刻的微秒级时间戳(UTC),由clock_gettime(CLOCK_MONOTONIC)生成,不受SET TIMESTAMP干扰 -
immediate_commit_timestamp:若事务被立即提交(无延迟复制),此值与前者一致;否则表示延迟提交发生时间 - 这两个字段只在
binlog_format=ROW+gtid_mode=ON下写入,解析需用mysqlbinlog --verbose查看注释行
别再依赖 binlog event header 里的 timestamp 做延迟分析或时间对齐——它从设计上就不是为精确计时服务的。真正要定位事务提交时间点,只认 original_commit_timestamp。


















