草草聊事

日志风暴打满 CPU——大量日志输出的隐形杀手

2026/06/19
3
0

日志风暴打满 CPU——大量日志输出的隐形杀手

本文是线上问题实战录系列的第 11 篇 叙事框架：现象 → 排查过程 → 根因 → 修复 → 预防

问题现象

某日上午，值班同学收到一条 P2 告警：认证网关服务 CPU 使用率超过 80%。与此同时，用户开始反馈登录响应变慢，接口 P99 从正常时的 80ms 飙升到 2.3s。

奇怪的是——QPS 平稳，没有促销活动，没有版本上线（昨天上的新功能，平稳运行了半天），没有 FullGC。CPU 到底在忙什么？

告警群首先炸了：

登录服务器，先看一眼 top：

Java 进程用了 687.3% CPU（8 核），us 74.3% — 大部分 CPU 消耗在用户态，不是系统调用。但同一个进程，CPU 这么均匀分布，不是单线程死循环的典型特征。

排查过程

第一步：看线程分布

用 top -Hp 看进程内各线程的 CPU 消耗：

24 个线程 CPU > 5%，每个大约 14-15%，非常均匀。这不像锁竞争（锁竞争应该是少数线程 RUNNABLE、大量线程 BLOCKED），更像是大家都在做同一件事。

第二步：jstack 看线程在干什么

抓线程栈，看看这些线程到底在执行什么代码：

22 个线程卡在 FileOutputStream.writeBytes！每个线程都在往日志文件写数据。日志框架走的是同步 appender，每次 log 调用都会触发文件 IO。

继续看详细栈帧：从 AuthServiceV1.verify() 的 log 调用 → Log4j2 的 AppenderControl.callAppender → OutputStreamManager.writeBytes → FileOutputStream.writeBytes。每个日志语句都要写一次文件。

第三步：检查日志量

既然问题在日志，看看日志写得多夸张：

半天时间，audit.log 1.2G，auth-service.log 987M。日志行数 1723 万行，磁盘写入带宽 25MB/s。磁盘 80% 使用率，按这个速度 14 天就会写满。

第四步：系统层面确认

用 vmstat 和 pidstat 看系统状态：

可运行线程队列（r）12+，上下文切换 12k/s，写带宽 25MB/s。IO 利用率 93.45%。

非自愿上下文切换 4k+/s，说明线程被频繁抢占。每次日志写文件都触发锁竞争和上下文切换，这就是 CPU 消耗的来源。

根因分析

问题定位到代码层面就清楚了。看这段代码：

三个致命问题叠加：

  1. 字符串拼接日志："收到验证请求: " + request.toString() — 即便日志级别是 INFO、debug 不输出，字符串拼接也在执行。request.toString() 序列化整个对象，每次都要构建字符串。

  2. 无日志级别保护：7 条 DEBUG 日志，没有 log.isDebugEnabled() 保护。框架内部仍要计算参数、构建日志事件对象。

  3. 同步文件 Appender：每写一条日志，线程都要等待文件 IO 完成。22 个线程并发写文件，争抢文件锁，上下文切换爆炸。

运营要求新增的审计规则在关键路径上输出完整请求报文。开发用最简单的方式加了一串 log.info("AUDIT|" + ...) 和 log.debug()。单体应用+高并发+同步日志+字符串拼接，量变引起质变。

lsof 也能佐证。8 个日志文件描述符，进程 IO 写 25MB/s（即每秒写约 25 万行日志）。一个认证请求要写 7 条日志，算下来每秒处理的请求数也就约 3.5 万，每秒产生 25 万行日志。

修复方案

修复方向有三个：

  1. 日志级别保护 — isDebugEnabled() 包裹，避免字符串拼接开销
  2. 参数化日志 — {} 占位符替代 + 拼接，懒加载
  3. 审计日志采样 — 从「每条都记」改为「采样 1%」

变更 diff 如下：

验证结果

上线后再次查看 top：

CPU 从 687% 降到 26.3%，sy 从 12.1% 降到 3.1%。写带宽从 25MB/s 降到正常水平。接口 P99 从 2.3s 回到 120ms。

对比测试结果也很直观——V1（日志风暴版本）处理 5000 个请求耗时 23.5 秒，V2（优化版本）仅需 1.2 秒，吞吐量差了近 20 倍。

避坑建议

  1. 日志是 IO 密集操作，高并发路径上每多一条日志就是多一次文件写入。线上环境保持 INFO 级别，DEBUG 留给开发环境。
  2. 永远用参数化日志 log.info("user={}", id)，不要用 + 拼接。前者在日志级别不满足时零开销，后者每次都要执行字符串拼接。
  3. 审计日志不能全量记，采样式审计在大流量场景下是必须的。1% 采样 + 异步写入（AsyncAppender）可以降低 99% 的日志开销。
  4. 监控磁盘 IO。CPU 飙高不一定是计算密集，也可能是日志 IO 拖垮的。监控组合：%iowait + kB_wr/s + Context Switches。
  5. Log4j2 推荐配置：AsyncAppender + immediateFlush=false + bufferSize 调大，能显著降低日志对业务线程的影响。

附：完整命令清单

# 查看 CPU 使用率
top -b -n 1 | head -25

# 查看进程内线程 CPU 分布
top -b -H -p {pid} -n 1 | head -30

# 抓线程栈看日志 IO
jstack {pid} | grep -E 'FileOutputStream|Log4j|Appender'

# 统计日志 IO 线程数
jstack {pid} | grep -c 'FileOutputStream.writeBytes'

# 查看日志文件大小
ls -lh /path/to/logs/
wc -l /path/to/logs/*.log

# 查看文件句柄
lsof -p {pid} | grep -E 'log|audit'

# 系统 IO 状态
vmstat 1 5
iostat -x 1 1

# 进程级 IO
pidstat -d -p {pid} 1 3
pidstat -w -p {pid} 1 5

# 进程上下文切换统计
cat /proc/{pid}/status | grep ctxt

📖 完整版带可复现 Demo → opencao.cn 📺 公众号「Ai拆代码的曹操」 🌟 知识星球「源阅会」(82877104)