本文是线上问题实战录系列的第 11 篇 叙事框架现象 → 排查过程 → 根因 → 修复 → 预防问题现象本文记录日志风暴引发 CPU 飙升的线上事故。现象认证网关服务 QPS 平稳无版本上线、无 FullGC但 CPU 飙至 687.3%P99 延迟从 80ms 升至 2.3s。排查过程top 发现 24 个线程 CPU 均匀分布14-15%/线程且无 BLOCKED 线程 → perf top 定位到 logback 写入方法占 CPU 首位 → 检查日志配置文件发现 ERROR 级别日志也会输出完整堆栈 → 日志输出量在无异常时仅 40 条/秒但某上游服务异常后激增至 8000 条/秒 → 每行日志的字符串拼接格式化和 IO 操作累积打满 CPU。修复方案日志级别调整 限流降级 异步 Appender 改造。排查过程第一步看线程分布用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.log1.2Gauth-service.log987M。日志行数 1723 万行磁盘写入带宽 25MB/s。磁盘 80% 使用率按这个速度 14 天就会写满。第四步系统层面确认用vmstat和pidstat看系统状态可运行线程队列r12上下文切换 12k/s写带宽 25MB/s。IO 利用率 93.45%。非自愿上下文切换 4k/s说明线程被频繁抢占。每次日志写文件都触发锁竞争和上下文切换这就是 CPU 消耗的来源。根因分析问题定位到代码层面就清楚了。看这段代码三个致命问题叠加字符串拼接日志收到验证请求: request.toString()— 即便日志级别是 INFO、debug 不输出字符串拼接也在执行。request.toString()序列化整个对象每次都要构建字符串。无日志级别保护7 条 DEBUG 日志没有log.isDebugEnabled()保护。框架内部仍要计算参数、构建日志事件对象。同步文件 Appender每写一条日志线程都要等待文件 IO 完成。22 个线程并发写文件争抢文件锁上下文切换爆炸。运营要求新增的审计规则在关键路径上输出完整请求报文。开发用最简单的方式加了一串log.info(AUDIT| ...)和log.debug()。单体应用高并发同步日志字符串拼接量变引起质变。lsof也能佐证。8 个日志文件描述符进程 IO 写 25MB/s即每秒写约 25 万行日志。一个认证请求要写 7 条日志算下来每秒处理的请求数也就约 3.5 万每秒产生 25 万行日志。修复方案修复方向有三个日志级别保护—isDebugEnabled()包裹避免字符串拼接开销参数化日志—{}占位符替代拼接懒加载审计日志采样— 从「每条都记」改为「采样 1%」变更 diff 如下验证结果上线后再次查看topCPU 从 687% 降到 26.3%sy从 12.1% 降到 3.1%。写带宽从 25MB/s 降到正常水平。接口 P99 从 2.3s 回到 120ms。对比测试结果也很直观——V1日志风暴版本处理 5000 个请求耗时 23.5 秒V2优化版本仅需 1.2 秒吞吐量差了近 20 倍。避坑建议日志是 IO 密集操作高并发路径上每多一条日志就是多一次文件写入。线上环境保持 INFO 级别DEBUG 留给开发环境。永远用参数化日志log.info(user{}, id)不要用拼接。前者在日志级别不满足时零开销后者每次都要执行字符串拼接。审计日志不能全量记采样式审计在大流量场景下是必须的。1% 采样 异步写入AsyncAppender可以降低 99% 的日志开销。监控磁盘 IO。CPU 飙高不一定是计算密集也可能是日志 IO 拖垮的。监控组合%iowaitkB_wr/sContext Switches。Log4j2 推荐配置AsyncAppender immediateFlushfalsebufferSize调大能显著降低日志对业务线程的影响。附完整命令清单# 查看 CPU 使用率top-b-n1|head-25# 查看进程内线程 CPU 分布top-b-H-p{pid}-n1|head-30# 抓线程栈看日志 IOjstack{pid}|grep-EFileOutputStream|Log4j|Appender# 统计日志 IO 线程数jstack{pid}|grep-cFileOutputStream.writeBytes# 查看日志文件大小ls-lh/path/to/logs/wc-l/path/to/logs/*.log# 查看文件句柄lsof-p{pid}|grep-Elog|audit# 系统 IO 状态vmstat15iostat-x11# 进程级 IOpidstat-d-p{pid}13pidstat-w-p{pid}15# 进程上下文切换统计cat/proc/{pid}/status|grepctxt
