先把结论放前面:线上 CPU 飙高的排查,是一个逐层收敛的过程——机器 → 进程 → 线程 → 方法 → 代码行。每一层都有固定的一两条命令,中间任何一层跳过,后面都会变成猜。
这篇按当时的实际顺序写。示例是一次真实故障:某服务 CPU 长期 95% 以上,重启后恢复,约两小时复发,GC 曲线看起来"还行",所以一开始所有人都往 GC 之外的方向想——结果绕了很久。
开始之前
先做一件事:把现场留下来。摘流量可以,但不要重启。重启会让你失去唯一能复现的样本,而下一次复现可能是三天后的凌晨。
Figure 01 · 收敛路径
五层收敛。跳过第三层直接看 jstack,是最常见的时间浪费。
第一步:确认烧 CPU 的确实是 JVM
不要相信告警面板上写的服务名。先在机器上确认三件事:负载有多高、是谁在烧、烧的是用户态还是内核态。
# 1) 负载 —— 三个数分别是 1/5/15 分钟平均,跟核数比才有意义
uptime
nproc
# 2) 谁在烧 —— 按 CPU 排序,只看前几行
top -b -n 1 -o %CPU | head -20
# 3) 用户态 vs 内核态 vs 等待 —— 每秒采一次,采 5 次
vmstat 1 5
关键是 vmstat 输出里的 us / sy / wa / st 四列:
| 特征 | 大概率方向 | 下一步 |
|---|---|---|
us 高(> 70) | 业务代码或 GC 在真算 | 继续走本文主线 |
sy 高 | 系统调用频繁:线程切换、大量小 IO、锁竞争 | 先看 cs 上下文切换数与线程数 |
wa 高 | 在等 IO,CPU 其实是"闲着忙" | 转去查磁盘 / 网络,不是 CPU 问题 |
st 高 | 虚拟机被宿主抢占 | 是资源超卖,找运维,不是你的代码 |
top 默认看到的是宿主机的核数和负载。要判断"是不是被 cgroup 限流了",得看 /sys/fs/cgroup/cpu.stat 里的 nr_throttled 和 throttled_usec——如果这两个数在涨,那 CPU 使用率贴着 limit 是结果不是原因,你要调的是 limit 或并发度。
第二步:从进程钻到线程
这是整条链路上最容易跳过、也最不该跳过的一步。jstack 打出来是几百个线程的快照,不先锁定线程号,你面对的是一堆无差别文本。
# 假设进程号 8123 top -Hp 8123 # 大写 H:按线程展示;再按 shift+P 按 CPU 排序
输出大概长这样,注意第一行的 PID 这一列此时是线程 ID:
PID USER PR NI VIRT RES %CPU %MEM TIME+ COMMAND 8371 app 20 0 12.4g 4.1g 99.3 26.1 47:12.88 java 8372 app 20 0 12.4g 4.1g 98.7 26.1 46:58.31 java 8375 app 20 0 12.4g 4.1g 97.9 26.1 45:03.06 java 8130 app 20 0 12.4g 4.1g 1.3 26.1 0:21.44 java
三个线程各自吃满一个核。把线程 ID 转成十六进制——因为 jstack 里的 nid 是十六进制:
printf "%x\n" 8371 # → 20b3 printf "%x\n" 8372 # → 20b4 printf "%x\n" 8375 # → 20b7
然后一条命令直接把这几个线程的栈捞出来(-A 40 是往下多打 40 行,栈深了就加大):
jstack 8123 > /tmp/jstack-$(date +%s).txt
grep -A 40 "nid=0x20b3" /tmp/jstack-*.txt
务必做的一件事
连着打三次 jstack,每次间隔 5 秒。单张快照只能告诉你"这一瞬间它在哪",三张才能告诉你"它是卡在这里,还是只是路过"。栈顶三次都一样 → 死循环或长时间计算;三次都在变但都在同一个包里 → 那个包就是热点。
读到的栈长这样
"http-nio-8080-exec-42" #142 daemon prio=5 os_prio=0 tid=0x00007f2c1c0d5800 nid=0x20b3 runnable
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$Loop.match(Pattern.java:4785)
at java.util.regex.Pattern$GroupTail.match(Pattern.java:4717)
at java.util.regex.Pattern$BranchConn.match(Pattern.java:4568)
... 省略 200 余帧同类帧 ...
at java.util.regex.Matcher.matches(Matcher.java:604)
at com.example.rule.RuleEngine.eval(RuleEngine.java:88)
三个信号叠在一起就可以下结论了:线程状态是 RUNNABLE(不是 BLOCKED、不是 WAITING,说明它真的在算)、栈深数百帧且全是 Pattern$...match、三次快照栈顶都在正则包里。这是正则回溯的教科书指纹。
第三步:栈看不出来的时候,改用采样
jstack 的盲区很明确:它只能给你几个瞬间。如果 CPU 是被大量短小方法均匀吃掉的(典型如序列化、字符串拼接、日志格式化),每张快照的栈顶都不一样,你就得不到结论。这时候上采样器。
方案 A:arthas(最快,不用传文件)
# 一行拉起,attach 到目标进程 curl -O https://arthas.aliyun.com/arthas-boot.jar java -jar arthas-boot.jar 8123 # 进入交互后: dashboard # 实时看线程/内存/GC,先扫一眼全局 thread -n 3 # 直接给出 CPU 占用最高的 3 个线程及其栈 thread -b # 找出正在阻塞其他线程的那个(死锁/长持锁) profiler start # 底层就是 async-profiler ... 等 30~60 秒 ... profiler stop --format html # 产出火焰图 HTML,路径会打在屏幕上
thread -n 3 基本上把第二步的三条命令合成了一条,日常我更常用它。但第二步的手工路径仍然值得会——不是所有线上环境都允许你 attach 一个 agent。
方案 B:async-profiler(更准,开销更低)
# 采 30 秒 CPU 样本,直接输出火焰图 ./profiler.sh -d 30 -e cpu -f /tmp/flame-8123.html 8123 # 如果怀疑是分配压力导致的 GC 风暴,换事件: ./profiler.sh -d 30 -e alloc -f /tmp/alloc.html 8123 # 如果怀疑是锁竞争: ./profiler.sh -d 30 -e lock -f /tmp/lock.html 8123
四类高频真凶的特征指纹
把过去几年遇到的归一归,线上 CPU 高基本落在这四类里。每一类都有一个几乎不会认错的指纹。
| 类型 | 指纹 | 确认命令 |
|---|---|---|
| GC 风暴 | 吃 CPU 的线程名是 GC task thread / G1 Conc;业务线程反而都在 WAITING |
jstat -gcutil 8123 1000 看 FGC 是否在快速增长、O 是否降不下去 |
| 死循环 / 自旋 | 同一个线程 nid 长时间满核,三次快照栈顶完全一致 |
直接读那一行代码。经典来源:HashMap 并发扩容、while 条件依赖非 volatile 变量 |
| 正则回溯 | 栈深数百帧且全是 Pattern$...match;只对特定输入触发 |
把线上那条输入拿下来单测;检查表达式里有没有嵌套量词 |
| 序列化 / 日志 | 栈顶每次都不同,但都在 jackson / logback 包内;火焰图上是一片宽平台 |
看日志级别是否误开 DEBUG;看是否在同步 appender 里打大对象 |
关于 GC:为什么"曲线看起来还行"会骗人
本文开头那次故障,最初被排除 GC 的理由是"监控上 GC 次数不高"。问题在于监控采的是次数,而 CPU 被吃掉取决于耗时占比。正确的看法:
# 每秒一次,看 10 次。重点不是绝对值,是变化趋势 jstat -gcutil 8123 1000 10 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 12.50 88.31 97.62 95.11 92.40 184 12.335 31 88.212 100.547
这里真正刺眼的是三个数:老年代 O 到了 97% 还在往上、FGC 已经 31 次、Full GC 累计耗时 FGCT 88 秒。用 GCT / 进程运行秒数 算出 GC 时间占比,超过 5% 就该处理,超过 20% 基本等于服务已经废了。
# 顺手确认存活对象到底是什么(会触发一次 Full GC,慎用;生产建议用 -histo:live 之外的方式) jmap -histo:live 8123 | head -20 # 更安全的做法:先 dump 再离线分析 jmap -dump:live,format=b,file=/tmp/heap-8123.hprof 8123
不是 CPU 的 CPU 问题
有几类现象长得很像 CPU 打满,但根因在别处。判断错了会白白花掉一整天。
cgroup 限流
容器专属
nr_throttled 持续增长,说明进程被强制掐住了时间片。表现是"CPU 100% 但吞吐上不去"。要调的是 limit 或线程池大小。
线程池配置
上下文切换
vmstat 里 cs 数万起跳、sy 明显高于 us。几百个线程抢十几个核,CPU 花在切换而不是计算上。
JIT 编译
只在启动后几分钟
线程名带 C2 CompilerThread。启动初期短暂高 CPU 是正常的,如果长期高,去看是不是有方法在反复去优化再重编译。
速查表
把上面所有命令按使用顺序压成一张表。线上真出事的时候从上往下走就行。
| # | 目的 | 命令 |
|---|---|---|
| 1 | 看整机负载与核数 | uptime · nproc |
| 2 | 看 us/sy/wa/st 分布 | vmstat 1 5 |
| 3 | 锁定进程 | top -b -n 1 -o %CPU | head -20 |
| 4 | 锁定线程 | top -Hp <pid> |
| 5 | 线程号转十六进制 | printf "%x\n" <tid> |
| 6 | 抓栈(连抓三次) | jstack <pid> > /tmp/js-$(date +%s).txt |
| 7 | 定位栈 | grep -A 40 "nid=0x<hex>" /tmp/js-*.txt |
| 8 | 确认 GC 是否是主因 | jstat -gcutil <pid> 1000 10 |
| 9 | 栈看不出来时采样 | profiler start → profiler stop --format html |
| 10 | 留证据再处理 | jmap -dump:live,format=b,file=… <pid> |
现场保留清单
如果只能在重启前抢救 60 秒,按这个顺序抓,之后就能离线复盘:
三张线程快照
for i in 1 2 3; do jstack $PID > /tmp/js-$i.txt; sleep 5; done。这是最便宜也最有信息量的一份证据。
线程级 CPU 分布
top -Hbp $PID -n 1 > /tmp/threads.txt。和上面三张栈能对上号,缺了它栈就没法定位。
GC 状态
jstat -gcutil $PID 1000 10 > /tmp/gc.txt,外加把 GC 日志文件本身复制走。
堆快照(可选)
堆大就慢,而且会 stop-the-world。只在怀疑内存泄漏时才做,纯 CPU 问题不需要。
这次故障的结局
根因是一条用户可配置的正则,遇到某类长字符串时进入指数级回溯
修复:给 Matcher 加超时中断 + 在配置保存时做表达式复杂度校验。上线后 CPU 从 95% 回到 12%。
补一句:那条正则在测试环境跑了半年都没事,因为测试数据没有那种长度。线上和测试的差别往往不在代码,在数据——这大概是这次排查里最值得记住的一条。