【背景】
MySQL 8.0.32 / InnoDB,核心 OLTP 库 32C/128G,innodb_buffer_pool_size=48G,binlog ROW + sync_binlog=1。一张约 9000 万行核心表,白天 OLTP 点查 + 短事务 QPS 5000~8000,P50 稳定 3~5ms,P99 平时 12~18ms。slow_query_log=ON,long_query_time=0.5(半年前从 1s 调下来的),log_slow_verbosity=verbose,slow log 落本地 NVMe(与数据盘同盘)。
【现象】
业务方反馈「接口偶发卡顿」,抓 2 周 P99:大部分时间 15ms,但每天 14:00~16:00 高峰期会出现 1~2 秒、300~800ms 的毛刺,频次约 10~30 次/天。关键观察:
- 毛刺窗口内,被记进慢日志的语句本身只有 20~40 条,单条 total_time 在 0.5~0.9s——「被记下来的慢语句」并不多;
- 但同一窗口内,一批「本不该慢」的普通点查(total_time < 0.5s,没进慢日志)P99 也同步抬到 200~500ms——它们没被记录,却在业务侧表现为卡顿;
- iostat 显示毛刺窗口 NVMe 写 await 从 0.1ms 涨到 1.5ms,但 util 仅 11%(不是带宽瓶颈);
- 怀疑方向有两个,但无法区分:
- (A) 慢日志的同步落盘(slow log 文件 write + fsync,与业务写入竞争同一块 NVMe / 同一份 OS page cache 写回)在高峰期成为 P99 抖动源之一;
- (B) 高峰期的真实根因是别的(LRU 逐出 / 锁排队 / group commit 对齐),慢日志只是「事后采样」,把真正慢的那 20~40 条记下来了,却漏掉了「被拖慢的普通点查」这一大批长尾。
【已尝试的排查与排除】
- 排除连接池:HikariCP pending=0;
- 排除 CPU:vmstat us+sy 峰值 58%;
- 排除 buffer pool 命中率整体崩溃:命中率毛刺窗口从 99.6% 掉到 98.9%,幅度不足以解释 200~500ms;
- 排除行锁:Innodb_row_lock_waits 毛刺窗口增量 < 5/min;
- 慢日志阈值 A/B:long_query_time 从 0.5 调到 0.2,慢日志条目从 ~2000/天 涨到 ~18000/天,但业务侧 P99 毛刺频次没有下降——说明「记录更多慢语句」并没有消除卡顿,反而印证 (B):真正拖慢的是那批没被记下的普通查询;
- 把 slow log 写到独立 NVMe 盘(与数据盘/日志盘分离)后重测:毛刺频次从 ~20/天 降到 ~8/天,P99 峰值从 500ms 降到 280ms——这强烈暗示慢日志落盘本身确实是 P99 抖动源之一(方向 A 成立),但还差一条量化证据链。
【期望得到的答案形态】
- 量化慢日志自身的 P99 贡献:在不停写、不影响业务的前提下,怎么测出「慢日志文件 write + fsync」占掉了多少尾延迟?
- 能不能用 performance_schema 的 i/o 等待事件(file 相关 event_name)或 sys 层,把 slow log 文件的写 IO 单独拆出来,和 data / redo / binlog 的写分开看?
- 有没有办法做 A/B(slow log 落独立盘 vs 同盘)拿到「毛刺频次 / P99 峰值」的量化对比,而不只凭体感?
- 阈值怎么定:long_query_time 到底该对着「我要修的慢语句」设,还是对着「我要观测的 P99 毛刺」设?有没有可复用的公式 / 经验值(比如基于当前 P99 的某个分位、或叠加 log_queries_not_using_indexes 的取舍)?
- 不漏尾又不淹没:高峰期 QPS 高、慢日志条目多时,除了调 long_query_time,还有没有更细的手段把「高频慢」和「偶发慢」分开统计?(比如 log_slow_rate_limit、或改用 performance_schema.events_statements_history_long + min_time 思路、或 pt-query-digest 的 --min-time 分层)
- 降慢日志自身开销的落地手段:独立盘之外,slow log 的写模式(同步 vs 异步)、log_slow_verbosity 的代价、slow log 文件轮转(max_size 太小导致频繁 rename/fsync)——这几项里哪个对 P99 影响最大?
希望有实战数据的朋友给一个「慢日志自身开销」的量化方法 + 阈值设定的可复用经验值。