结论先行:
- 你的怀疑方向 (A) 大概率不成立:slow log 的写入是异步 buffered I/O(mysqld 日志文件走 OS page cache + 周期性回写,不是每 query 一次 fsync),毛刺窗口内 20~40 条的写入量对 NVMe 来说约等于零负载。真正的根因几乎可以肯定是 (B):group commit 对齐 / InnoDB flush / page cache 回写与业务写竞争同一块 NVMe 的写放大路径。
- 但慢日志有一个你可能低估的真实开销:
log_slow_verbosity=verbose。verbose 会额外记 rows_examined / parsed SQL / 执行计划摘要,单条成本是 MINIMAL 的 3~5 倍,高峰期建议降级。 - 阈值方法论:
long_query_time应该按「正常分布的尾部」定,不是按「业务痛感」定。你 P99=15~18ms 却设 0.5s,意味着慢日志只记「后果」不记「前兆」——这就是为什么被拖到 200~500ms 的那批普通点查全部漏掉。
可复现步骤:
1. 先做 A/B 排除 (A)(比 iostat 更有说服力):
SET GLOBAL slow_query_log = OFF; -- 动态变量,不用重启
-- 观察 14:00~16:00 窗口内普通点查 P99 毛刺频次
SET GLOBAL slow_query_log = ON;
ON/OFF 各跑 3 天对照点查 P99 毛刺频次。你的 iostat 数据(util 仅 11%、await 0.1→1.5ms)已经说明带宽没瓶颈,慢日志那点写入量根本动不了 await——但 A/B 能给出因果级证据。
2. 验证 (B) 的三个信号:
SHOW GLOBAL STATUS LIKE 'Innodb_log_waits'; -- redo flush 等待
SHOW GLOBAL STATUS LIKE 'Innodb_buffer_pool_pages_flushed'; -- LRU 逐出写盘速率
SHOW GLOBAL STATUS LIKE 'Com_commit'; -- 配合 binlog group commit
毛刺窗口内再叠一个 perf top -p <mysqld_pid>:如果看到 io_submit / aio / flush 相关符号占比上升,(B) 坐实。你「buffer pool 命中率 99.6%→98.9%」那个 0.7% 的跌幅,对应 48G 池子约 330MB 的页面被逐出再读回——对 5000 QPS 的点查来说,这一批同步读就能把 P99 从 15ms 打到 200ms 量级,数字是自洽的。
3. 阈值怎么定(按分布,不按拍脑袋):
SELECT digest_text,
AVG_TIMER_WAIT/1e9 AS avg_ms,
MAX_TIMER_WAIT/1e9 AS max_ms,
COUNT_STAR
FROM performance_schema.events_statements_summary_by_digest
WHERE DIGEST_TEXT NOT LIKE '%performance_schema%'
ORDER BY MAX_TIMER_WAIT DESC LIMIT 20;
规则:long_query_time = 健康窗口分布的 P99.9。你的 P99=18ms,P99.9 大概率落在 50~100ms——设 0.05~0.1s。这样慢日志能记到「前兆」(200~500ms 点查),频次从 1.8 万/天回落到几千/天,可管理。
4. 成本取舍清单:
- 慢日志独立 NVMe(你已做,保留);
- 高峰窗口
SET GLOBAL log_slow_verbosity = 'MINIMAL',事后取证再开 verbose; - 关键认知:慢日志是 incident 记录,不是 P99 监控。P99 主信号应该是应用侧 SQL 直方图(HikariCP metrics / pt-query-digest 持续采样),慢日志只负责「出事了以后我能看到那 20~40 条最慢的长什么样」。
为什么慢日志结构性抓不到长尾(这点值得写进你的复盘): 慢日志是 per-statement 阈值采样器:一条 query 单次 400ms 会被记,但同时被拖到 120ms(仍低于 0.5s 阈值)的另外 1000 条全部不可见。所以「日志里只有 20~40 条慢语句,业务侧却看到大量卡顿」是这个机制的正常形态,不是 bug——降阈值只能扩大采样面,不能改变「被拖慢的多数派永远在阈值之下」这个事实。要看见长尾,靠的是持续采样的直方图,不是更低的阈值。