一条 log.info 把 P99 从 30ms 拖到 2.3 秒：同步日志刷盘的锁竞争与 AsyncAppender 调参

一、现象与背景

先给数字。我们一个出账查询服务，Spring Boot 3.2.4 + JDK 17 + Logback 1.4.14，4 实例、每实例 8C16G，应用日志落在云盘（ESSD PL1，3000 IOPS / 125 MB/s）。这个服务平时 P50 稳定在 28ms，非常健康。

但每天 10:00–10:40 出账高峰，P99 会间歇性从 30ms 飙到 2300ms，毛刺持续几分钟。诡异的是：CPU 只有 35%，HikariCP 活跃连接 12/50 远没打满，慢 SQL 日志干净，网络 RTT 正常。影响面是出账高峰这 40 分钟里约 6% 的请求 P99 > 1s，前端超时后自动重试，网关 502 比例从基线 0.3% 涨到 2.1%。

「CPU 不高、DB 没满、网络正常，P99 却秒级毛刺」——这套组合拳，我第一反应不是查下游，而是查进程内部谁在串行化。

二、根因：同步 Appender 的实例锁 × 慢 IO 放大

根因在 Logback 的同步写盘模型上。RollingFileAppender（继承自 FileAppender）在 append 时对 appender 实例持锁（内部 OutputStream 的写被 synchronized 串行化）。也就是说：同进程里所有线程打同一份文件日志，都要抢同一把锁。

平时这把锁的持有时间是微秒级——写盘快、页缓存命中，抢锁几乎无感。但出账高峰两个条件叠加了：

1. 日志量从平时约 200 行/s 飙到约 3000 行/s；
2. 云盘 IOPS 撞上 ESSD PL1 的 3000 IOPS 上限被限流，write/flush 的 syscall 在内核 IO 队列里排队，单次 flush 从约 0.1ms 涨到约 80ms。

关键在于放大机制：这把锁是「每线程串行」的。一个线程卡在慢 flush 上，后面所有打日志的业务线程全在锁上排队。结果是 P50 基本不受影响（只有少数线程真正碰到慢 flush），但锁队列把尾部延迟放大到了秒级——这就是「单点慢 IO 被并发锁放大成长尾」。我抓 thread dump 时，能看到 10 多个业务线程全停在 ch.qos.logback.core.FileAppender.subAppend 的锁等待上，而那一刻磁盘 util 接近 100%。

一句话：不是日志「慢」，是**「锁 + 慢 IO」的组合**把一次 80ms 的盘抖动，放大成了 12 个线程 × 排队 = 2.3s 的 P99。

三、具体做法（可复现）

1. 换 AsyncAppender，把锁竞争从业务线程挪到独立 worker：

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>/var/log/app/app.log</file>
  <immediateFlush>false</immediateFlush>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <fileNamePattern>/var/log/app/app.%d{yyyy-MM-dd}.log</fileNamePattern>
    <maxHistory>14</maxHistory>
  </rollingPolicy>
</appender>

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>8192</queueSize>
  <discardingThreshold>0</discardingThreshold>
  <neverBlock>true</neverBlock>
  <appender-ref ref="FILE"/>
</appender>

<root level="INFO">
  <appender-ref ref="ASYNC"/>
</root>

2. immediateFlush 从默认 true 改成 false。 默认每次 append 都 flush，等于每行一次 syscall，正好喂给被限流的盘；改 false 后让内核页缓存批量刷，单行成本骤降。

3. 磁盘侧： 出账高峰把日志盘独立出来，并把 ESSD 从 PL1（3000 IOPS）升到 PL2（20000 IOPS），消除限流这一根因。

4. 高峰降级日志： 出账窗口把部分 DEBUG 临时降到 WARN，日志量从 3000 行/s 压回 800 行/s。

5. 加监控： 暴露 AsyncAppender 的队列积压深度（queueSize 当前占用）接 Prometheus，设 80% 告警。

上线后出账高峰 P99 从 2300ms 回落到 65ms，网关 502 回到 0.3% 基线。

四、踩过的坑（反直觉）

• AsyncAppender 默认会丢日志。 discardingThreshold 默认是 20，意味着队列用到 80% 时就开始丢弃 INFO/DEBUG/TRACE、只留 WARN/ERROR。很多人以为「上了 Async 就永不丢」，其实默认是丢的。要 discardingThreshold=0 才不丢。
• neverBlock=true 队满是硬丢。 对审计/对账类日志这是灾难——你省了延迟，丢了证据。要不要 neverBlock，取决于这条日志丢不丢得起。
• immediateFlush=false 的代价是 kill -9 丢尾段日志。 崩溃恢复时最后几十行可能不在盘上，排查时要心里有数。
• Async 不是免费午餐。 它把锁竞争从 N 个业务线程转移到一个 worker 线程，还多了一个额外线程；真正不解决盘限流，它只是把「P99 毛刺」换成「丢日志」。

五、结论与可复用清单

结论： P99 毛刺 + CPU 不高 + DB 没满 + 网络正常，这个组合的第一嫌疑是进程内同步写盘的实例锁被慢 IO 放大，而不是下游。

排查清单：

1. 看毛刺时刻的日志量（行/s）和云盘 IOPS 是否撞上规格上限被限流；
2. 抓 thread dump，看业务线程是否批量停在 FileAppender.subAppend 的锁等待；
3. 上 AsyncAppender + immediateFlush=false + 独立盘/升盘，三件事一起做才治本；
4. 明确 discardingThreshold / neverBlock 的丢日志语义，按日志重要度取舍；
5. 加 AsyncAppender 队列积压深度监控，别等 502 涨了才发现。