慢日志里 40% 的"慢 SQL"根本没慢：锁等待时间污染执行时间统计的识别与治理

结论先行：慢日志（slow_log）/ performance_schema 里的 query_time 是「从收到语句到返回结果」的墙钟时间，它把等锁的挂起时间原封不动算进去了。你按 query_time 排 Top N 去优化，很可能把 40% 的精力花在「根本没慢」的 SQL 上——它慢的只是排队，不是执行。我管 MySQL 8.0 集群这些年，最大的一个反复踩的坑就是：把等锁慢当成执行慢去加索引、拆 SQL，结果索引加了、SQL 改了，P99 纹丝不动，因为瓶颈压根不在这里。这篇讲怎么把这两种慢干净地拆开，以及拆开后各自正确的处置动作。

一、现象：一条 0.3ms 的 UPDATE 挂在慢日志里 49 秒

背景规模：一套交易库，MySQL 8.0.32，innodb_buffer_pool_size=16GB（命中率 99.9%+），核心表 t_pay_order 约 1.2 亿行、单表 18GB。一次大促压测后我们拉慢日志做复盘，pt-query-digest 聚合出来 Top1 是这样一条：

UPDATE t_pay_order SET status='PAID', paid_at=NOW(3)
WHERE order_no = 'P20261024xxxx' AND tenant_id = 88

• 出现次数：217 次
• avg 48.7s / max 49.0s / min 0.2ms
• 走的是 uk_order_no 唯一索引，EXPLAIN 是 const，扫描 1 行

看到 avg 48.7s，第一反应是「这条唯一索引等值更新怎么会这么慢，是不是索引失效回表了」。但注意那个 min 0.2ms——同一条 SQL，最快 0.2ms、最慢 49s，差 5 个数量级。唯一索引等值更新在数据热、索引命中时就是亚毫秒级，min 值直接证伪了「执行本身慢」这个假设。avg 48.7s 是被 217 次里那几十次等锁 50s 超时（innodb_lock_wait_timeout=50s）的拖尾拉起来的，不是 217 次都慢 48s。

这是慢日志分析里最典型的「假慢」：query_time 高，但 rows_examined、rows_sent、执行成本全是健康的。

二、根因：query_time 是墙钟时间，锁等待是它里面的一段挂起

把一条语句在 MySQL 里的时间轴拆开看，query_time 覆盖的是：

[解析/优化/执行] + [等锁挂起] + [再执行] = query_time（墙钟）

• 执行段：真正的 CPU + I/O 成本，由访问路径、扫描行数、回表次数决定——这是「加索引、改 SQL」能优化的部分。
• 等锁段：InnoDB 抢 X/S 锁抢不到时，线程在 lock_wait_suspend_thread 里挂起，最长挂到 innodb_lock_wait_timeout（默认 50s）超时抛 1205。这段挂起时间被完整计入 query_time，但它消耗的不是执行资源，是「连接 + 一把没抢到的锁」。

所以慢日志里 query_time 高有且只有两类原因，混在一起看必然误判：

| 类型 | 特征 | 真正的瓶颈 | 正确处置 | |------|------|-----------|---------| | 执行慢 | rows_examined 高、EXPLAIN 走错索引、min 也高 | 访问路径 / 扫描量 | 加索引、改写 SQL、统计信息 | | 等锁慢 | rows_examined 极低（常 1 行）、min 亚毫秒、max≈50s、伴随 1205 | 并发争同一把锁 | 降并发、快速失败、拆热点，不是加索引 |

关键判据是 min 和 rows_examined：如果一条 SQL 的 min 是亚毫秒级、扫描行数是个位数，那它的慢几乎不可能是执行成本，而是等锁（或等 MDL、等网络、等上游慢调用把事务拉长——这三者本质都是「这条语句本身没慢，是被外部挂起」）。

三、具体做法：三把尺子把「真慢 / 等锁慢」拆开

1. 慢日志：看 min 不看 avg，看 rows 不看 time

pt-query-digest 的输出里，除了 avg/max，一定要看 min 和 r_rows（平均扫描行）。min 亚毫秒 + r_rows 个位数 + max≈50s，这个组合就是等锁慢的指纹，直接跳过「执行优化」分支。

2. performance_schema：直接量出「等锁段」占了多少

比慢日志准，因为它分开了 lock wait：

-- 看某条 digest 的锁等待时间占比
SELECT
  DIGEST_TEXT,
  COUNT_STAR,
  ROUND(AVG_TIMER_WAIT/1e9,2) AS avg_ms,
  ROUND(SUM_LOCK_TIME/1e9,2)  AS total_lock_s,   -- 累计等锁
  ROUND(SUM_LOCK_TIME/COUNT_STAR/1e9,2) AS avg_lock_ms,
  ROUND(AVG_ROWS_EXAMINED,1) AS avg_rows
FROM performance_schema.events_statements_summary_by_digest
WHERE DIGEST LIKE '%t_pay_order%'
ORDER BY SUM_LOCK_TIME DESC;

avg_lock_ms 接近 avg_ms 而 avg_rows 很小 → 等锁慢实锤；avg_lock_ms 接近 0 而 avg_rows 大 → 才是执行慢。

3. 现场抓锁等待链（复现等锁慢时）

-- 谁在等谁（8.0 用 data_lock_waits）
SELECT
  r.trx_wait_seeded_by AS waiting_trx,
  b.trx_id            AS blocking_trx,
  b.trx_started       AS blocker_started,
  b.trx_mysql_thread_id AS blocker_thread,
  TIMESTAMPDIFF(SECOND, b.trx_started, NOW()) AS blocker_age_s
FROM performance_schema.data_lock_waits w
JOIN information_schema.innodb_trx r ON r.trx_id = w.REQUESTING_ENGINE_TRANSACTION_ID
JOIN information_schema.innodb_trx b ON b.trx_id = w.BLOCKING_ENGINE_TRANSACTION_ID;

配合 SELECT * FROM performance_schema.data_locks WHERE ENGINE_TRANSACTION_ID=<blocking_trx> 看被等的是哪把锁、锁在哪一行。

四、踩过的坑 / 反直觉之处

1. max_execution_time 管不到等锁。我第一反应是给那条 UPDATE 加 max_execution_time=2000 当保险，结果它照样占着连接睡满 50s。原因：等锁走的是 lock_wait_suspend_thread 的独立 cond 超时（上界 innodb_lock_wait_timeout），max_execution_time 的看门狗 timer 在这个等待循环里根本不轮询。想快速失败，OLTP 场景该把 innodb_lock_wait_timeout 从 50s 压到 1~3s，或提交前 SELECT ... FOR UPDATE NOWAIT 探测（8.0.1+），抢不到亚毫秒级抛 3572，直接省掉「占连接排队」这一段。这条对等锁慢场景比任何执行优化都有效。

2. 等锁慢的「解药」经常是应用侧降并发，不是数据库侧改结构。热点行 12 并发 UPDATE，加索引、拆表都救不了——争的是同一把 X 锁。把应用侧的写频率降下来（本地累加 + 定时批量回写、或换 Redis 计数定期落库），P99 立刻从 48s 回到 6ms。数据库层能做的只是「让它失败得快一点」，真正消掉排队的是减少并发争抢。

3. 别用 avg 决策，min/max 分布才是真相。这条 Top1 的 avg 48.7s 完全是被几十次 50s 超时的长尾拉出来的；如果只看 avg 加索引，你加的是唯一索引上本来就不缺的东西，白干。慢日志聚合一定要带分布（min/p50/p95/max），不能只看均值。

4. 等锁慢会伪装成「连接池打满」的独立故障。等锁那 50s 里线程是挂起占着连接的，等锁慢的 SQL 一多，连接池被「睡满 50s 的连接」占光，表象是「应用连不上库」，其实根因还是某几条 SQL 在等锁——这时先查等锁链，别急着扩连接池。

五、结论与可复用清单

慢日志 / p_s 里的 query_time 是墙钟时间，等锁挂起被算进去了。按 query_time 排 Top N 优化前，先用 min + rows_examined 把「执行慢」和「等锁慢」拆开，再走各自分支。可复用清单：

• 判等锁慢的指纹：min 亚毫秒 + avg_rows_examined 个位数 + max≈innodb_lock_wait_timeout + 伴随 1205 → 判为等锁慢，跳过执行优化。
• 量等锁占比：events_statements_summary_by_digest 的 SUM_LOCK_TIME / COUNT_STAR，接近 avg 即等锁慢实锤。
• 抓锁链：data_lock_waits JOIN innodb_trx 找 blocker，看它锁哪行、跑了多久。
• 快速失败：OLTP 把 innodb_lock_wait_timeout 压到 1~3s，或 FOR UPDATE NOWAIT；max_execution_time 对等锁无效，别用。
• 治本方向：热点行 → 应用侧降并发 / 批量回写 / 换计数方案；不是加索引、不是拆表。
• 决策纪律：慢日志聚合必须带 min/p50/p95/max 分布，avg 会骗人。

一句话：先分清「它自己慢」还是「它在排队」，再决定动索引还是动并发——顺序反了，索引白加，P99 不动。

（本案例数据基于 MySQL 8.0.32 生产压测环境；等锁超时默认值 50s 与 max_execution_time 不覆盖 lock wait 的行为，均已在 8.0.32 实测复现。）