JVM 线上排查：GC、线程与 Arthas

线上 Java 服务出问题，排查顺序基本固定：先看是不是 GC 导致 CPU 高或停顿长，再看内存有没有泄漏，最后才用 Arthas 定位到具体方法。顺序反了会浪费大量时间——在每分钟十次 Full GC 的状态下用 trace 找慢方法，看到的方法每个都是慢的。

判定顺序

1. jstat -gcutil <pid> 1000    GC 频率与单次停顿是否超标
2. top -H -p <pid>             CPU 高的线程是哪几个，把 tid 转成 16 进制
3. jstack <pid>                线程栈：业务线程 / GC 线程 / 编译线程
4. jmap -histo:live <pid>      堆里什么对象最多
5. arthas dashboard / thread   实时看线程与内存
6. arthas trace / watch        定位到具体方法与入参
7. arthas profiler             火焰图确认 CPU 热点

先排除 GC，再谈业务代码。GC 导致的 CPU 高与慢方法导致的 CPU 高处置方式相反：前者调内存与分配，后者改代码。

GC：先读 jstat

jstat -gcutil <pid> 1000        # 每秒一次，看各代使用率与 GC 次数、耗时
jstat -gc <pid> 1000            # 看具体容量（KB），确认堆大小与晋升速度
jstat -gccause <pid> 1000       # 多两列 LGCC/GCC，看最近一次 GC 的原因

jstat -gcutil 各列含义与判读：

列含义判读
S0 / S1两个 Survivor 区使用率总有一个接近 0，两个都高说明晋升压力大
EEden 区使用率每次都接近 100%，说明分配速率很高
O老年代使用率持续上涨不回落＝疑似泄漏；稳定在某水平属正常
M元空间使用率持续上涨要查动态代理与反射生成的类
CCS压缩类空间一般不关注
YGC / YGCTYoung GC 次数与总耗时用 YGCT/YGC 算平均停顿
FGC / FGCTFull GC 次数与总耗时有 Full GC 就要看频率与原因
GCTGC 总耗时与进程存活时间对比，得出 GC 占 CPU 的比例
观测值判断处置方向
YGC 平均停顿 < 50ms，频率低于每秒 1 次正常无需处理
YGC 每秒数次且 E 每次打满分配速率高，大量临时对象减少大对象与不必要的装箱、拷贝
FGC 每小时 0~1 次，每次 < 1s可接受观察趋势即可
FGC 每分钟多次明确故障，停顿叠加会造成超时查晋升过快、堆过小、显式 System.gc()
O 在 Full GC 后仍持续上涨内存泄漏jmap -histo:live 加 heap dump 分析
GCT 占进程时间 > 10%GC 吃掉太多 CPU调堆与收集器，或减少分配
M 持续上涨元空间泄漏查动态类生成，设 -XX:MaxMetaspaceSize

注意 jstat -gcutil 只能看到「发生了几次 GC」，看不到「为什么」，原因要靠 GC 日志。

GC 日志

开启方式（JDK 8 与 JDK 9+ 写法不同）：

# JDK 8
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/var/log/app/gc.log
# JDK 9+
-Xlog:gc*,gc+age=trace,safepoint:file=/var/log/app/gc.log:time,uptime,level,tags

关键字段判读：

字段含义判读
Pause Young (Allocation Failure)年轻代分配失败触发正常，说明瓶颈在分配速率
Pause Full (Ergonomics)老年代压力触发的 Full GC频繁出现要查晋升与泄漏
Pause Full (System.gc())代码里显式调用去代码搜 System.gc() 并禁止
Pause Full (Heap Dump Initiated GC)dump 或诊断触发确认是不是人为操作
123M->45M(512M) 0.0312345 secs回收前后占用与停顿 31ms单次停顿超 500ms 就要评估对 P99 的影响
allocation stallG1 中应用线程被迫协助回收回收速度跟不上分配，需要减少分配或加堆
回收前后占用几乎不变GC 无效对象都在老年代且仍被引用，查泄漏

内存：找大对象

jmap -histo <pid> | head -30                            # 不触发 GC，含垃圾对象，无停顿
jmap -histo:live <pid> | head -30                       # 触发 Full GC 后统计存活对象，有停顿
jmap -dump:live,format=b,file=/tmp/heap.hprof <pid>     # 导出堆快照，停顿可达数秒
观测值判断
[C、java.lang.String 占据前二正常，通常是大字符串与日志缓冲
某业务对象数量与请求量级同增且不释放有集合在无限增长或本地缓存未设上限
直接内存上涨但堆平稳堆外泄漏，查 Netty、文件映射、MaxDirectMemorySize
jmap -histo:live 与 jmap -histo 差异巨大大量短命对象，属于分配压力而非泄漏
出现 OutOfMemoryError: Java heap space导出 dump 后分析支配树，不要只看 top 类

生产上 jmap -histo:live 与 jmap -dump 都会引发 Full GC 级别停顿，必须在低峰期做，并先把实例从负载均衡摘除。

线程：抓栈的时机与技巧

jstack <pid> > /tmp/jstack-$(date +%H%M%S).txt
jstack -l <pid> | grep -A20 'deadlock'      # 末尾会打印 Found one Java-level deadlock
top -H -p <pid>                              # 线程级 CPU，取 PID 列
printf '%x\n' 12345                          # 转 16 进制，对应 jstack 里的 nid=0x3039
观测值判断
三次栈顶都是同一方法该方法所在的资源是阻塞点
大量 BLOCKED (on object monitor)锁竞争，用 jstack -l 找锁持有者
Found one Java-level deadlock死锁，只能改加锁顺序或减小锁粒度
线程数持续上涨线程池泄漏，见线程池与协程泄漏章节
RUNNABLE 但 CPU 不高在等 IO（socketRead）或 JNI

一次 jstack 只能看到瞬间。生产上至少抓三次、间隔 5 秒，否则会把某个恰好路过的方法误判为热点。

Arthas 在生产的使用姿势

Arthas 的价值是不重启、不加日志就能观察运行中的方法，但多数命令有性能开销，必须按「观察范围从小到大」使用：

命令用途生产注意
dashboard全局概览：线程、内存、GC、运行时秒级刷新，开销低，可长时间开
thread -n 3CPU 最高的 3 个线程栈开销低，排查 CPU 高的首选
thread -b找阻塞其他线程的线程开销低
trace com.x.OrderService getOrder打印方法内部调用链耗时默认采样，加 -n 5 限次；不要对高频方法长开
watch com.x.OrderService getOrder '{params, returnObj, throwExp}' -x 2看入参、返回值、异常用条件表达式过滤，避免刷屏
profiler start / profiler stop生成火焰图（async-profiler）有采样开销，生产不要超过几分钟
ognl读静态字段、调方法能改运行时状态，谨慎使用

常用姿势：先用 thread -n 3 找出忙线程，再用 trace -n 5 看该方法的内部耗时分布，最后用 watch 抓一次具体入参复现问题。定位到这一层就够了，再往下应该改代码加日志。

巡检项

  • GC 日志必须开启并归档，至少保留 7 天。
  • jstat 关键指标（YGC 频率、FGC 频率、O 使用率、GCT 占比）进监控并告警。
  • 堆大小与收集器配置纳入配置管理，生产禁止调用 System.gc()。
  • 预发环境定期跑死锁检测，提前发现加锁顺序问题。
  • Arthas 只在内网可达，关键操作留痕。

小结：JVM 排查先看 GC、再看内存、最后看方法，用 jstat -gcutil 判断频率与停顿，用 GC 日志判断原因，用 jmap -histo:live 找大对象，用三次 jstack 采样找阻塞点，Arthas 的 thread -n 3、trace、watch 按观察范围从小到大使用并控制开销。

笔记加载中…

标签：#故障排查 #运维

返回知识库