解析 MySQL 慢查询 commit 慢与 binlog 慢事务的差异

核心结论：为何两者常常不匹配？

导致慢查询中 commit 慢而 binlog 慢事务不慢（或反之）的最主要原因，在于它们记录的时间段截然不同：binlog 慢事务仅统计到“主库将 binlog 落盘”为止；而慢查询的 commit 耗时还包含了“等待半同步从库 ACK”及后续的网络通信时间。

这种差异使得我们能看到大量的 COMMIT 出现在慢查询日志中，但在基于 binlog 的分析工具里表现正常。理解这一区别是进行高级故障排查的关键。

技术原理：两个指标的判定边界

要理清这个差异，需要拆解 MySQL 内部执行一个显式事务时产生的 Event（事件流）及其对应的时间点：

第一步：理解 Binlog 慢事务的计算公式

在 binlog 日志中，一个完整的事务主要由以下 Event 组成，其时间戳含义如下：

• QUERY_EVENT：通常代表事务的开始（如 BEGIN），或者是第一条 DML 语句的执行起始时间。
• XID_EVENT / GTID_LOG_EVENT：这是由 COMMIT 命令触发的，代表事务提交时的时间点。

因此，Binlog 慢事务时间 = XID_EVENT 时间 - QUERY_EVENT 时间。

这个计算过程截止于主库将事务写入 binlog buffer 并执行了系统调用（fsync）将其同步到磁盘（取决于 sync_binlog 参数设置）。一旦落盘，binlog 层面的计时就结束了。

第二步：理解慢查询日志中 COMMIT 耗时的判定标准

客户端看到的 COMMIT 语句耗时（即慢查询日志记录的 Query_time），其流程比上述更晚。它包含以下步骤：

主库 Binlog 落盘 + 传输给从库 + 等待从库回复 ACK（若开启半同步/组复制）。

具体时序逻辑可简化为：

1. T1: 插入语句执行完毕。
   (此时已满足 INSERT 的慢查询判定阈值)
2. T2: 收到 XID_EVENT (Binlog 落盘)。
   (此时满足 Binlog 慢事务判定)
3. T3: 发送 binlog 给从库，并等待从库确认。
   (如果是半同步模式，这里可能发生网络阻塞等待)
4. T4: 收到从库 ACK 或超时后返回结果给客户端。
   (此时满足 Client Commit 耗时判定)

客户端 Commit 慢查耗时 ≈ T4 - T2。

实验验证：人为制造差异场景

为了直观展示这种差异，我们可以模拟一个半同步复制环境下，由于从库处理缓慢（模拟 ACK 延迟）导致的现象。

操作准备

假设主库和从库开启了半同步复制 (rpl_semi_sync_master_enabled=1)。我们在主库执行以下脚本：

-- 1. 开启事务
BEGIN;

-- 2. 第一次获取时间 (模拟事务起始点 T1)
SELECT now();

-- 3. 快速执行 DML
INSERT INTO it VALUES(10);

-- 4. 制造业务逻辑上的延时 (模拟复杂的业务逻辑或长时间运行的 SELECT/JOIN)
SELECT sleep(10);

-- 5. 第二次获取时间 (此时业务逻辑结束，准备发起 Commit，接近 T2)
SELECT now();

-- 6. 执行 Commit
COMMIT;

现象观察

在上述实验中，SLEEP(10) 发生在 Insert 之后、Commit 之前。这会让整个会话持有资源。

• Binlog 慢事务表现：
  当 COMMIT 触发时，MySQL 会先将之前的 DML 写入 binlog。由于 sleep 的存在，从 BEGIN 到 BINLOG FSYNC 完成的时间大约为 10 秒多（主要受 sleep 影响，这部分在 binlog 里是被计入的，因为 fsync 是在 sleep 结束后才做的）。如果我们只看 commit 这一步本身是否异常，Binlog 并没有显示出“Commit IO 很慢”。
  实际测试中，Binlog 记录的时间差约为 11 秒。
• 慢查询 (Client-side) 表现：
  如果此时我们挂起从库，使其无法及时返回 ACK，主库在 COMMIT 阶段会陷入长时间的 WAIT 状态。这段等待完全发生在 Binlog 落盘之后。
  最终客户端拿到的 COMMIT 耗时可能会高达 20~30 秒甚至更长。
  实际测试中，MySQL 记录的 Commit Query Time 为 21 秒。

日志对比证明

我们可以对比两边的输出：

#220612 22:20:54 ... GTID_LOG_EVENT ...
#220612 22:20:43 ... Query   thread_id=43    exec_time=1 ... BEGIN
...
# at 12496
#220612 22:20:54 server id 613306  end_log_pos 12527 ... Xid = 547
COMMIT/*!*/;
注释：这里我们看到 XID_EVENT 时间为 22:20:54，QUERY_EVENT 为 22:20:43。差值约 11s。Binlog 到此认为事务结束了。

# Time: 2022-06-12T22:21:15.746223Z
# User@Host: root[root] @ localhost []  Id:    43
# Query_time: 21.641090  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0
SET timestamp=1655043675;
commit;

显而易见，客户端看到的 Commit 耗时（21.64 秒）远远大于 Binlog 记录的该事务整体时长（11 秒）。那多出来的 10 秒去哪了？就是在等待从库 ACK 的过程中流逝的。

排查指南：如何利用这一差异定位问题？

理解了两者的分界线，我们可以根据日志的表现反向推断出系统可能存在的问题：

• 场景一：慢查询有 COMMIT 慢，但 binlog 中没有对应的长事务。
  • 极大概率原因：半同步复制 (Semi-sync Replication) 或 InnoDB Group Replication (MGR) 的主节点 AFTER_COMMIT 钩子函数卡住。
  • 具体细节：如果是 MGR，可能是 before_commit_hook 在处理其他节点消息。
  • 排查动作：检查主库与从库之间的网络延迟，检查从库负载是否过高导致 ACK 堆积。
• 场景二：binlog 中有长事务，但慢查询没有 COMMIT 慢。
  • 可能原因：事务中包含大量的慢 SELECT 查询，或者是因为锁等待时间长。
  • 注意：如果使用的是自动提交（Implicit Commit），则无法通过简单的 `QUERY` 减 `XID` 来准确计算，因为每个语句都在单独提交。
• 场景三：只有 INSERT/DML 本身的查询慢。
  • 如果显式事务中的 DML 耗时本身就很长（例如大表 Join），那么无论是 Binlog 慢事务还是客户端慢查询，都会同时记录下这段时间。

总结

MySQL 慢查询中的 Commit 慢，本质上衡量的是“事务对前端可见的耗时”，其中包含了网络和副本同步成本；而 Binlog 慢事务衡量的是“数据库引擎内部持久化数据的耗时”。

对于 DBA 而言，不要仅仅盯着 slow_log 里的长事务找答案。如果你发现大量的 COMMIT 挂在慢查询里，请务必优先检查你的半同步复制环境、网络健康状况以及 fsync 级别的存储性能。

以上就是 MySQL 慢查询中 commit 慢和 binlog 中慢事务的区别的详细解析，更多关于 MySQL 性能分析与优化的资料请关注本站其它相关文章！