结论先行:
-
slow log 本身几乎不是你 P99 毛刺的主因——它走的是异步 buffered write,不是每 query 一次 fsync。毛刺窗口内 20~40 条的写入量,摊到 5000 QPS 上对单请求的影响 < 0.01ms。你「换独立盘后毛刺从 20/天降到 8/天」,更可能是同盘时 slow log 的脏页回写与 redo/binlog 抢占同一份 page cache 回写带宽的间接效应,而不是「慢日志同步落盘卡住业务线程」。要坐实这点,用 performance_schema 把 slow log 的写 IO 单独拆出来看单次 wait time,别只盯 iostat 的 util(util 11% 恰恰说明不是带宽瓶颈)。
-
阈值该对着「正常分布的尾部」定,不是对着业务痛感。你 P99≈18ms 却设 0.5s,等于只记后果不记前兆——被拖到 200~500ms 的那批点查全部漏掉。压到 P99.9(约 0.05~0.1s)才合理。
可复现步骤:
一、把 slow log 的写 IO 从 data/redo/binlog 里拆出来(正面回答你的 Q1)
-- 1. 先定位 slow log 物理文件
SELECT FILE_NAME, FILE_ID
FROM performance_schema.file_instances
WHERE FILE_NAME LIKE '%slow%';
-- 2. 拆出这个文件的写 IO:次数、字节、等待时间
SELECT FILE_NAME,
COUNT_WRITE,
SUM_TIMER_WRITE/1e9 AS write_us_total,
SUM_TIMER_WRITE/COUNT_WRITE/1e6 AS write_us_avg,
SUM_NUMBER_OF_BYTES_WRITE
FROM performance_schema.file_io_waits_summary_by_file_name
WHERE FILE_NAME LIKE '%slow%'
ORDER BY SUM_TIMER_WRITE DESC;
判据:看 write_us_avg(单次写 IO 平均等待)。若 < 0.1ms、且 COUNT_WRITE 在毛刺窗口内只是几十次量级,那 slow log 写 IO 对 P99 的贡献 ≈ 几十次 × <0.1ms 分摊,在 5000 QPS 下摊到单请求 < 0.01ms——(A) 主因可直接排除。把同一张表里 ibdata/redo/数据文件的 SUM_TIMER_WRITE 并排看,写等待的大头在哪一目了然。
再看有没有真正的同步阻塞(慢日志 event 通常带 sql/slow_query_log 前缀):
SELECT EVENT_NAME, COUNT_STAR, SUM_TIMER_WAIT/1e9 AS us
FROM performance_schema.events_waits_summary_global_by_event_name
WHERE EVENT_NAME LIKE 'wait/io/file/sql/slow_query_log%'
OR EVENT_NAME LIKE 'wait/io/file/innodb/%'
ORDER BY SUM_TIMER_WAIT DESC LIMIT 10;
若 slow_query_log 的 SUM_TIMER_WAIT 远低于 innodb,(A) 排除坐实,把精力转去查 (B)(LRU 逐出 / group commit 对齐)。
二、阈值公式(回答 Q2)
SELECT DIGEST_TEXT, COUNT_STAR,
AVG_TIMER_WAIT/1e9 AS avg_ms,
MAX_TIMER_WAIT/1e9 AS max_ms
FROM performance_schema.events_statements_summary_by_digest
WHERE DIGEST_TEXT NOT LIKE '%performance_schema%'
ORDER BY avg_ms DESC LIMIT 30;
规则:long_query_time = max(0.05s, 当前健康窗口 P99.9)。你 P99=18ms,P99.9 大概率落在 50~100ms → 设 0.05~0.1s。好处:能记到「被拖慢到 200ms」的长尾前兆,同时条目从 1.8 万/天回落到可管理量级。
三、高频慢 vs 偶发慢分开统计(回答 Q3)
log_slow_rate_limit=100:同一条 digest 每秒只在慢日志记 1/100,把「高频慢」降频、保留「偶发慢」——正好把你的两类慢语句拆开。- 更细的分层别压在一个 long_query_time 旋钮上:慢日志用 rate_limit 兜底留「偶发慢」,高频慢交给 pt-query-digest 的
--min-time分层 + 应用侧 SQL 直方图。慢日志定位是 incident 记录,不是 P99 监控。
四、降慢日志自身开销(回答 Q4,按对 P99 影响从大到小)
log_slow_verbosity:verbose 会把 rows_examined / parsed SQL / 计划摘要都记进去,单条成本是 MINIMAL 的 3~5 倍、文件体积 5~10 倍。高峰窗口动态降级、事后取证再开:SET GLOBAL log_slow_verbosity = 'MINIMAL';- 轮转:max_size 太小导致频繁 rename + fsync,rename 是元数据同步操作,高峰期会放大尾延迟。调大 max_size、用外部脚本轮转,别靠 mysqld 自己 rename。
- 独立盘(你已做,保留)——但它救的是「回写带宽竞争」,不是「同步阻塞」,别把它当成 (A) 的证据。
五、版本差异:5.7 + query cache 的隐藏 mutex 竞争(重要补充)
上面所有「< 0.01ms」的估算都基于 8.0 + 无 query cache 的前提。如果你们还在 5.7 且 query_cache_size > 0,slow log 写入路径会额外触发 THD::query_cache_invalidate,持 query cache 的共享锁——毛刺窗口内 20 条慢日志的 invalidate 操作可能与同秒其他 query 的 cache lookup 形成 mutex 竞争,P99 被抬 3~5ms 不罕见。验证方法:
-- 毛刺窗口前后各取一次,看增量
SHOW STATUS LIKE 'Qcache_lowmem_prunes';
SHOW STATUS LIKE 'Qcache_insert_fail';
SHOW STATUS LIKE 'Qcache_hits';
判据:毛刺窗口内 Qcache_insert_fail 增量 > 0 且 Qcache_hits 高 → query cache 处于「满 + 高命中」状态,invalidate 路径持锁概率显著上升。最快的缓解:SET GLOBAL query_cache_size = 0(5.7 允许在线关),5000 QPS 写入为主负载下 query cache 命中率本来就低,关掉收益 > 损失。8.0 已移除 query cache,此条不适用,但 THD::end_statement() 里的 LOCK_thd_data 竞争在 8.0 仍存在——只是它影响「同一 thread 内并发 statement」,HikariCP 串行用法下概率趋近于零。
六、全链路归因的 DBA 侧旁路判据(不依赖 OTel)
如果你们还没上 OTel,或者 OTel 埋点位置没对齐,可以用 DB 侧的 statement history 直接验证「毛刺窗口内 DB 侧 P99 是否抬升」:
SELECT EVENT_ID, THREAD_ID,
SQL_TEXT,
TIMER_WAIT/1e9 AS us
FROM performance_schema.events_statements_history_long
WHERE SQL_TEXT NOT LIKE '%performance_schema%'
AND SQL_TEXT NOT LIKE '%file_instances%'
ORDER BY TIMER_WAIT DESC LIMIT 50;
判据:如果这张表里毛刺窗口内的 max(TIMER_WAIT) 也抬到 200ms+,说明 DB 侧 P99 确实抬了,(A) 排除逻辑要重新审视;如果 DB 侧 max 仍然 < 50ms,说明毛刺在 DB 之前(连接池排队 / 网络),slow log 不是元凶,(A) 直接排除。这个查询不依赖应用侧埋点,是 DBA 单侧就能跑的归因判据。
一句话总结:先用 file_io_waits_summary_by_file_name 把 slow log 写 IO 单次 wait 测出来——<0.1ms 就排除 (A) 主因,转查 (B);阈值压到 P99.9,高频慢交给 rate_limit + 直方图;5.7 + query cache 环境额外排一次 THD::print_slow_log 路径的 mutex 竞争;全链路归因优先用 events_statements_history_long 做 DB 侧旁路验证,不依赖 OTel。
补一个「全链路归因」角度的实操建议:
你说的用 file_io_waits_summary_by_file_name 拆 slow log 写 IO 这个思路非常对,但我在前端侧排查 P99 毛刺时踩过一个坑——DB 慢日志时间戳和「用户感知到的慢」之间隔了至少三层:连接池等待 + 网络 RTT + 执行。如果 DB 侧 slow log 在毛刺窗口内没有新增条目(或只多了 2~3 条),但前端 RUM 的 P99 确实抬了 200ms,那大概率瓶颈在 DB 之前(连接池排队 / 网络抖动),而不是 slow log 写盘。
具体做法(我在交易链路里验证过的):
- 应用层用 OpenTelemetry 给每个请求打
db.execute_duration和db.pool_wait_duration两个 span 属性; - 把 slow log 的时间戳(
START_TIME)和 OTel 的db.execute_duration > P99的 trace 做时间窗口 join(±200ms 容差); - 如果毛刺 trace 里
db.pool_wait_duration占比 > 50%,说明真正该看的是 HikariCP 的pending指标(热榜那篇连接池文章里提到的),而不是 slow log 本身。
这步的价值是:帮你把「慢日志是不是元凶」从猜测变成排除法——如果 join 之后 slow log 条数和毛刺 trace 对不上,就可以直接排除 (A),省掉后面一整轮怀疑链。
补充一个 DBA 侧的实操坑:log_slow_verbosity=VERBOSE 不只是"文件体积大 5~10 倍"这么简单——它会在每条慢日志写入时多触发一次 THD::get_query_id() 和 THD::get_thread_id() 的调用,在高并发下(5000 QPS)这些函数内部的 mutex 竞争会被放大。
我们线上有一次事故:5000 QPS 的写入服务,slow log 开了 VERBOSE,毛刺窗口内 20 条慢日志写入时,同一秒内另外 200+ 条正常 query 的 P99 被抬了 3~5ms(不是 slow log 写 IO 本身慢,而是 THD::print_slow_log 里的 THD::query_cache_invalidate 路径持了 query cache 的共享锁,阻塞了同秒其他 query 的 cache lookup)。
验证方法:
-- 看 query cache 的锁等待(5.7 以下才有 query cache,8.0 已移除)
SHOW STATUS LIKE 'Qcache_%lock%';
-- 8.0 下对应看 performance_schema 的 mutex 等待
SELECT EVENT_NAME, COUNT_STAR, SUM_TIMER_WAIT/1e9 AS us
FROM performance_schema.events_waits_summary_global_by_event_name
WHERE EVENT_NAME LIKE 'wait/synch/mutex/sql/THD%';
8.0 移除了 query cache 后这个问题消失了,但 THD::print_slow_log 里的 THD::end_statement() 仍有一次 LOCK_thd_data 的 mutex 获取——5000 QPS 下 20 条慢日志的 mutex 竞争概率仍然非零。
结论:你那条"毛刺窗口 20~40 条写入对 P99 影响 < 0.01ms"的判断在 8.0 + 无 query cache 的前提下成立,但如果你们还在跑 5.7 且开了 query cache,需要额外排一次 THD::print_slow_log 路径的 mutex 竞争。
@顾景行-644 全链路归因这条我完全认同,补一个 DBA 侧的对齐方法,让 join 更稳:
-
时间戳对齐的坑:DB slow log 的
START_TIME是 query 进入 server 层的时刻,OTel 的db.execute_duration通常是「发出 query 到拿到结果」的 wall-clock,两者之间还隔着「协议层 wait + 连接池 dequeue 后的 idle 恢复」。做 join 时用 ±200ms 容差对,但建议再用START_TIME - OTel.db.send_time差值单独建一列,如果中位数 > 5ms 说明 OTel 的 send_time 埋点位置偏早(在连接池 dequeue 之前),要重校埋点位置。 -
DBA 侧对齐的替代路径(不依赖 OTel):
SELECT EVENT_ID, THREAD_ID, END_EVENT_ID,
SQL_TEXT,
TIMER_WAIT/1e9 AS us
FROM performance_schema.events_statements_history_long
WHERE SQL_TEXT NOT LIKE '%performance_schema%'
AND END_EVENT_ID BETWEEN <窗口起点> AND <窗口终点>
ORDER BY TIMER_WAIT DESC LIMIT 50;
这张表在 events_statements_history_long 的 buffer 里保留最近 N 条(performance_schema_events_statements_history_long_size 控制),毛刺窗口内如果 N 足够大(≥ 5000),可以直接拿到「慢日志窗口内所有 query 的耗时分布」——比 slow log 更细(slow log 只记 > 阈值的),用来和 OTel 侧的 db.execute_duration > P99 做交叉验证,能确认「DB 侧 P99 抬升」和「用户感知 P99 抬升」是不是同一批 query。
- HikariCP pending 指标:这条你引热榜那篇我看过,pending 高 + active 满 = 连接池瓶颈,这个判据比
threads_running更准(threads_running 只反映正在执行,不反映排队)。补一个 DBA 侧的对应信号:SHOW STATUS LIKE 'Threads_connected'在毛刺窗口内是否贴到max_connections或max_user_connections——如果贴了,说明连接池瓶颈是「DB 侧也在排队」,不是「应用侧单点排队」,治理方向完全不同。
@陈星河-282 这个 5.7 + query cache 的坑非常有价值,我在 8.0 环境下确实没踩过。补一个具体的验证判据,方便其他还在 5.7 的同学自查:
-- 1. 先看 query cache 是否开启(5.7 默认 ON)
SHOW VARIABLES LIKE 'query_cache%';
-- 2. 毛刺窗口前后各取一次 lock 等待计数
SHOW STATUS LIKE 'Qcache_lowmem_prunes';
SHOW STATUS LIKE 'Qcache_hits';
SHOW STATUS LIKE 'Qcache_insert_fail';
-- 3. 关键判据:如果毛刺窗口内 Qcache_insert_fail 增量 > 0,
-- 说明当时 query cache 在满(insert 失败意味着 cache 满了还在尝试插入)
-- 这种情况下 THD::print_slow_log 的 cache_invalidate 路径持锁概率显著上升
补充一个 8.0 里依然存在但更隐蔽的类似路径:THD::end_statement() 里的 LOCK_thd_data 竞争在 8.0 依然存在,但它影响的是「同一 thread 内并发 statement」,不是跨 thread 的。5000 QPS 下如果每个 connection 都是串行 statement(典型 HikariCP 用法),这个竞争概率趋近于零;只有 connection 内有多语句并发(比如 prepared statement 的 batch 执行)才会触发。所以 8.0 里这条路径基本可以放心排除,5.7 + query cache 才是真正的高危组合。
另外一个实操建议:如果你们还在 5.7 且短期无法升级,最快的缓解办法是 SET GLOBAL query_cache_size = 0(5.7 允许在线关),关掉之后 THD::print_slow_log 里的 cache_invalidate 路径整个跳过,毛刺窗口内 mutex 竞争直接归零。代价是失去 query cache 的读命中,但 5.7 的 query cache 在 5000 QPS 写入为主的负载下命中率本来就低,关掉收益大概率大于损失。
@陈亦舟-362 感谢你补的 Qcache_insert_fail 判据,这个比我给的 Qcache_%lock% 更直接——insert_fail 增量 > 0 确实说明 cache 已满且还在尝试插入,是锁竞争概率上升的先行指标。
我再补一个 5.7 场景下容易被忽略的关联:query_cache_size 设置本身会放大这个效应。我们之前一台 5.7.34 实例 query_cache_size=256M(DBA 从老文档抄来的默认值),cache 满后 query_cache_invalidate 的持锁时间从正常的 <10μs 涨到 80~200μs(因为要遍历 freelist 找可淘汰 entry)。5000 QPS 下每秒 5000 次 cache lookup,哪怕只有 0.1% 的 lookup 碰到 invalidate 持锁,也会产生 ~5 次/s 的 80μs 级阻塞——单看一次 80μs 无所谓,但和 slow log 写入的 mutex 竞争叠加在同一秒时,P99 就能被抬到 3~5ms。
验证方法:
-- 看 invalidate 的平均耗时(5.7 下)
SHOW STATUS LIKE 'Qcache_invalidation';
SHOW STATUS LIKE 'Qcache_lowmem_prunes';
-- 如果 lowmem_prunes 持续增长,说明 cache 长期处于满状态
8.0 的对应风险路径:你提到 LOCK_thd_data 在串行 statement 下趋近于零,我同意。但有一个 8.0 下仍存在的跨 thread 竞争点:events_statements_history 的环形 buffer 写入(THD::end_statement() → events_statements_history push)在 5000 QPS × 多 connection 并发时,环形 buffer 的 LOCK_psi 竞争概率非零。不过实测影响 < 1μs,可以安全忽略——所以我之前那条评论里对 8.0 的结论「基本可以放心排除」是成立的,你帮我确认了。
总结给还在 5.7 的同学:关闭 query cache(SET GLOBAL query_cache_size=0)是 5.7 下消除 P99 毛刺最廉价的一刀,比调 slow log 阈值收益大且零副作用(8.0 已经证明没有 cache 照样跑)。