日志打印导致CPU飙高问题排查

---

面试记录 2026-10-22

题目：日志打印导致 CPU 飙高问题排查

难度：high

标签：practice/debug, os/cpu, os/load, difficulty/high

评分：⭐⭐☆☆☆（2/5）

我的回答

qps没有什么变动,但是cpu标高,需要检查下具体是什么线程导致的cpu标高,top -hp 确认具体线程,然后使用jstack导出线程栈查看具体栈帧信息,找到对应方法;

检查方法内是否存在什么问题,检查最新更新的代码,是否有什么特殊调整;

点评

优点：排查的起手式是对的——QPS 没涨但 CPU 高，说明"单请求成本"变高了；用 top -Hp 定位线程、jstack 抓栈，方向没错。

不足：① 没有回答"日志为什么耗 CPU"，而这正是这题的核心。日志的开销不只是写文件：字符串拼接、toString、JSON 序列化、日志 pattern 格式化、锁竞争、syscall 与磁盘 fsync，每一项都可能烧 CPU，且 %usr 与 %sys 高法不同；② jstack 是瞬时快照，抓 10 次可能 9 次都抓到线程在 RUNNABLE 但栈很浅，不足以定位热点，应该用采样类工具（async-profiler/JFR）看火焰图；③ 没有验证手段——临时调高日志级别或关掉某条日志做 A/B，是最快的证伪方式；④ 没提异步日志队列打满后的降级行为（丢弃或同步写），这恰恰是"平时没事、压测/大促突然飙高"的常见原因。

补充：日志类 CPU 问题有个很实用的判别——如果是序列化/拼接开销，%usr 高，火焰图热点在 StringBuilder.append、ObjectMapper.writeValueAsString、toString；如果是写盘开销，%sys 高、%iowait 也可能高，火焰图热点在 FileOutputStream.writeBytes、fsync。两者优化手段完全不同：前者降日志量/懒求值，后者换异步 appender 或降刷盘策略。

完整讲解

第一部分：知识重点剖析

核心考点定位：考察能否把"日志"从"一行代码"拆成一条完整的成本链——参数求值 → 格式化 → 序列化 → 加锁入队 → IO 写盘，并据此选择优化手段。

知识点拆解：

1. 参数求值陷阱：log.debug("user=" + user) 和 log.debug("user={}", JSON.toJSONString(user)) 都会在级别关闭时照样执行拼接与序列化。正确写法是 if (log.isDebugEnabled()) 或使用惰性求值的 Supplier 形式。这是最常见的"日志偷 CPU"。
2. 格式化与序列化：占位符替换、时间格式化（SimpleDateFormat 还是线程不安全的）、异常栈的 printStackTrace 字符串化（深层异常栈的字符串化成本极高）、大对象 JSON 序列化。
3. 同步 appender 的锁竞争：logback 的 OutputStreamAppender 对每个 appender 加锁，高并发下线程在锁上排队，表现为 %sys 高、上下文切换多，火焰图能看到 ReentrantLock.lock 与 write。
4. IO 与刷盘：每条日志一次 write 系统调用；immediateFlush=true 会频繁 flush；磁盘慢或日志文件过大时，写放大明显。容器里日志走 stdout 还要经过 runtime 的日志管道，量大会拖垮节点。
5. 异步日志的两面性：log4j2 Disruptor / logback AsyncAppender 把写盘移出业务线程，但队列满时有 Discard、Block 两种策略——Block 会把业务线程重新拖回 IO，Discard 会丢日志。队列容量与消费者线程数配置不当，问题只是从"慢"变成"丢"或"卡"。
6. 其他放大器：循环体内打日志（N 次循环 N 条日志）、DEBUG 级别被误开到线上、日志采集 agent（Filebeat/Fluent Bit）CPU 抢占、MDC/ThreadLocal 的 traceId 生成与拷贝。

按「底层原理 → 设计权衡 → 工程实践」递进排列。

第二部分：考察方向与延伸递进

考察方向：

• 深度：能否说清日志成本链的每一环，并区分 %usr（算）与 %sys（写/锁）两种表现。
• 广度：能关联到日志框架（logback/log4j2）、异步队列、容器 stdout、日志采集、JVM 内存分配。
• 应用：给出"先证伪再定位再优化"的完整路径，以及异步日志的取舍。

延伸递进面试题：

1. 为什么火焰图里日志相关栈很高，但 jstack 抓不到？

• 解答要点：jstack 是瞬时快照，采样点落在浅栈或阻塞点的概率高；火焰图是周期性采样聚合，能反映时间分布。热点定位要用 async-profiler/JFR，jstack 更适合看死锁、阻塞和线程状态。

1. 异步日志会不会丢日志？怎么权衡？

• 解答要点：会。队列满时按策略丢弃或阻塞。金融/交易类场景要可靠就选 Block 并给足队列与磁盘，日志量大的普通业务可选 Discard + 采样，关键是显式选择而不是默认。

1. 线上 CPU 高，怀疑日志，怎么快速验证？

• 解答要点：动态调高日志级别或加 TurboFilter 关掉可疑 logger，观察 CPU 是否立刻回落；同时看日志文件增长速度（ls -l 两次对比）与火焰图中 logger 栈占比。回落后再逐条二分定位到具体日志语句。

第三部分：面试者参考回答（三步法口语化，300-400 字）

【一句话结论】

面试官您好，QPS 没涨但 CPU 高，说明单请求变贵了；日志的成本不在"打"这一下，而在参数求值、格式化、加锁和写盘这四段。

【三点展开】

第一，先解释为什么日志能吃掉 CPU。最常见的是级别判断失效，debug 关了但字符串拼接和 JSON 序列化照样执行；其次是同步 appender 的锁竞争和每条日志一次 write 系统调用。看火焰图能区分：热点在 StringBuilder 或序列化就是算得多，热点在 write 或 lock 就是写得贵。前者 %usr 高，后者 %sys 高。

第二，定位手段不能只靠 jstack。jstack 是瞬时快照，热点方法很难恰好抓到，应该用 async-profiler 或 JFR 采样看火焰图，再结合日志文件增长速度、日志条数突增来交叉验证。如果是循环里打日志，日志行数会明显暴涨，一眼就能看出来。

第三，验证和优化。最快的证伪是把可疑 logger 的级别临时调高或加 TurboFilter 关掉，看 CPU 是否立刻回落；回落后再二分到具体那一行。优化上优先去掉无谓的序列化和循环内日志，再考虑异步 appender，但要明确队列满时是丢弃还是阻塞。

【一句边界】

当然，如果日志是走 stdout 交给容器 runtime 收集，瓶颈可能不在应用线程，而在节点的日志管道或采集 agent，这时候应用侧怎么优化都没用，要看节点层面的 CPU 和磁盘。

---