yangshan.link / 山之志 · 后端工程笔记

首页/文章/JVM CPU 排查

线上排障

JVM 线上 CPU 飙高排查:从 top 到火焰图的一条完整链路

重启能好,两小时后复发。真正难的不是工具,是在告警响的那五分钟里按对顺序。

先把结论放前面:线上 CPU 飙高的排查,是一个逐层收敛的过程——机器 → 进程 → 线程 → 方法 → 代码行。每一层都有固定的一两条命令,中间任何一层跳过,后面都会变成猜。

这篇按当时的实际顺序写。示例是一次真实故障:某服务 CPU 长期 95% 以上,重启后恢复,约两小时复发,GC 曲线看起来"还行",所以一开始所有人都往 GC 之外的方向想——结果绕了很久。

开始之前

先做一件事:把现场留下来。摘流量可以,但不要重启。重启会让你失去唯一能复现的样本,而下一次复现可能是三天后的凌晨。

Figure 01 · 收敛路径

机器 进程 线程 方法 代码行 uptime / vmstat top / pidstat top -Hp jstack / profiler 火焰图 每一层只回答一个问题,不跳层 回答不了就停下来补数据,而不是往下猜

五层收敛。跳过第三层直接看 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 就消耗在它自己身上,而不是它调用的下游。

四类高频真凶的特征指纹

把过去几年遇到的归一归,线上 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 秒,按这个顺序抓,之后就能离线复盘:

0~15s

三张线程快照

for i in 1 2 3; do jstack $PID > /tmp/js-$i.txt; sleep 5; done。这是最便宜也最有信息量的一份证据。

15~25s

线程级 CPU 分布

top -Hbp $PID -n 1 > /tmp/threads.txt。和上面三张栈能对上号,缺了它栈就没法定位。

25~35s

GC 状态

jstat -gcutil $PID 1000 10 > /tmp/gc.txt,外加把 GC 日志文件本身复制走。

35~60s

堆快照(可选)

堆大就慢,而且会 stop-the-world。只在怀疑内存泄漏时才做,纯 CPU 问题不需要。

这次故障的结局

根因是一条用户可配置的正则,遇到某类长字符串时进入指数级回溯

修复:给 Matcher 加超时中断 + 在配置保存时做表达式复杂度校验。上线后 CPU 从 95% 回到 12%。

补一句:那条正则在测试环境跑了半年都没事,因为测试数据没有那种长度。线上和测试的差别往往不在代码,在数据——这大概是这次排查里最值得记住的一条。

← 上一篇从 RBAC 到 ABAC