2691 字
约 8 分钟
21
S05-X17 · JVM 问题定位工具链:JFR、MAT 与 async-profiler

线上变慢时,最顺手的动作是“挂个 profiler 看看”,结果常常是拿到一张读不懂的图,然后回到原点。问题不在工具,在于没先确定要回答哪个问题:谁在吃 CPU、谁在吃内存、谁在等锁、这次 GC 为什么停这么久。四类问题的证据来源不同,选错工具等于拿体温计量血压。


1. 四件工具的分工

工具 回答的问题 证据形态 对线上进程的影响
JFR 过去一段时间发生了什么事件 .jfr 二进制事件记录 按配置而定,常开可控
jcmd 此刻的现场是什么样 文本 / JSON 快照 部分子命令会 STW
MAT 内存被谁持有、为何没回收 .hprof,离线分析 转储时 STW
async-profiler 时间花在哪段调用栈上 火焰图 / collapsed 采样,开销随频率增长

它们是接力关系:JFR 指出“十分钟内多次超阈值停顿”,MAT 指出“大头挂在一个静态 Map 上”,async-profiler 指出“CPU 三成耗在它的扩容”。缺一步,结论都是猜的。

$ jcmd 5123 VM.flags | tr ' ' '\n' | grep -E 'Xmx|Xms|GC|FlightRecorder'
$ jcmd 5123 GC.heap_info

先 VM.flags 确认这台机器到底开了什么:以为开了 JFR,其实启动脚本那行被注释;以为堆是 4G,其实 -Xmx 被环境变量覆盖成 1G。


2. JFR:把运行时变成可回放的事件流

2.1 三种开启方式

方式 命令形态 适用场景
启动参数 -XX:StartFlightRecording=... 新部署,或可重启的服务
运行时附加 jcmd <pid> JFR.start 不能重启的线上进程
编程式 jdk.jfr.Recording API 按业务事件开停
java -XX:StartFlightRecording=duration=0,filename=/tmp/app.jfr,settings=profile,maxsize=256m -jar app.jar

$ jcmd 5123 JFR.start name=incident settings=default duration=180s filename=/tmp/incident.jfr
$ jcmd 5123 JFR.dump  name=incident filename=/tmp/incident-now.jfr   # 不结束先取一份
$ jcmd 5123 JFR.stop  name=incident
$ jcmd 5123 JFR.configure                                            # 当前生效配置

duration=0 + maxsize 是环形缓冲写法:文件不无限增长,出事时 dump 出来正好是最近一段窗口。

2.2 default 与 profile 的差别

维度 default.jfc profile.jfc
定位 可长期常开 短窗口深度排查
jdk.ExecutionSample 周期 20 ms 10 ms
事件覆盖 核心事件 追加分配、锁、IO 等细粒度事件
相对开销 低,典型量级在个位数百分比内(按 JDK 17 核对) 明显更高,随事件密度上升

低配机器上用 profile 常开是典型错误:采样周期减半、事件变多,开销不是线性的,小规格容器上可能直接把 CPU 打满。

2.3 事件类型与开销

事件 记录内容 典型用途
jdk.ExecutionSample 周期性 Java 栈采样 CPU 热点(受 safepoint 影响)
jdk.NativeMethodSample native 栈采样 JNI、系统调用
jdk.ObjectAllocationSample 分配抽样(JDK 16 起替代 TLAB 系列) 分配热点,按速率自适应抽
jdk.JavaMonitorEnter / jdk.ThreadPark monitor 阻塞、park 阻塞与时长 锁竞争、队列等待
jdk.GCPhasePause / jdk.GarbageCollection 停顿阶段与回收概要 停顿归因
jdk.ClassLoad / jdk.SocketRead 类加载、IO 事件与耗时 Metaspace 问题、慢 IO

“常开是否可接受”看三件事:事件集、采样周期、写入磁盘速率。default + maxsize 在多数服务型应用上属可接受量级;判断标准是 jfr summary 里的事件总数与文件增长速率。

2.4 怎么读

$ jfr summary /tmp/incident.jfr
 Duration: 3 min 0 s
 Event: jdk.ExecutionSample   Number of Events: 18234
 Event: jdk.GCPhasePause      Number of Events: 41

$ jfr print --events jdk.GCPhasePause --stack-depth 0 /tmp/incident.jfr
$ jfr view hot-methods /tmp/incident.jfr     # JDK 17 起的内置聚合视图
$ jfr view gc-pauses /tmp/incident.jfr

先 summary 定窗口与事件量级,再 print 单类事件,最后 view 聚合。直接 print 整个文件会刷出几十万行,读不出任何东西。


3. 堆转储:三种触发与它的停顿代价

方式 触发条件 停顿代价 什么时候用
-XX:+HeapDumpOnOutOfMemoryError 抛 OOM 时自动 进程已异常,代价无所谓 生产都该加,配 -XX:HeapDumpPath
jcmd <pid> GC.heap_dump 手动 STW,堆越大停得越久 现场可控、能接受短暂停顿
jmap -dump:live,format=b 手动,live 先 Full GC STW + 一次 Full GC 只要存活对象且承担得起
java -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/dump -jar app.jar
$ jcmd 5123 GC.heap_dump /data/dump/heap-$(date +%H%M).hprof
$ jmap -dump:live,format=b,file=/data/dump/live.hprof 5123

动手前确认三件事:磁盘余量(文件与堆使用量同量级)、停顿窗口(避开高峰或先摘流量)、路径权限(用启动 JVM 的同一用户写)。


4. MAT 的四个核心视图

视图 回答的问题 使用时机
Histogram 哪个类实例最多、浅堆占多少 第一眼找异常类
Dominator Tree 哪个对象持有量最大,删掉能释放多少 找内存大头
Leak Suspects 自动给出的 suspect 与引用链 快速起手,不能当结论
Path to GC Roots 从 GC Root 到目标的完整路径 回答“为什么它没被回收”
$ ./ParseHeapDump.sh /data/dump/heap.hprof org.eclipse.mat.api:suspects \
    org.eclipse.mat.api:overview -vmargs -Xmx6g    # MAT 自己也要内存

引用链读法最容易做错:MAT 默认展示所有引用,含 WeakReference、SoftReference。排除它们(exclude weak/soft references)之后得到的路径才是真正让它活着的那条。


5. async-profiler:四种事件与火焰图

事件 采什么 回答的问题
cpu CPU 上正在执行的 Java/native 栈 谁在烧 CPU
alloc 分配点(按 TLAB 采样) 谁在造垃圾、造在哪
lock monitor 争用与等待 谁在等锁、等了多久
wall 墙钟,不论线程是否在 CPU 上 谁在等(IO、锁、sleep)
$ ./asprof -e cpu  -d 30 -f /tmp/cpu.html   5123   # CPU 火焰图
$ ./asprof -e alloc -d 30 -f /tmp/alloc.html 5123  # 分配热点
$ ./asprof -e lock -d 30 -f /tmp/lock.html  5123   # 锁争用
$ ./asprof -e wall -d 30 -f /tmp/wall.html  5123   # 墙钟:在跑 + 在等
$ ./asprof -e cpu -d 30 -o collapsed -f /tmp/cpu.txt 5123   # 便于 diff

wall 是最被低估的一种。cpu 只回答“CPU 花在哪”:瓶颈在数据库等待、锁、Thread.sleep 的服务,cpu 图会显得很平,于是被误判成“代码没问题”。wall 按墙钟采所有线程,阻塞的栈会以最宽的形态出现——宽的那段就是时间真正流走的地方。

火焰图读法三条:宽度 = 该栈帧占全部样本的比例,不是耗时绝对值也不是调用次数;深度 = 调用链,自底向上时 root 在底部,顶端窄尖是叶子;横向顺序无意义,合并按字母排序,不代表时间先后。自顶向下(inverted)适合问“这个入口下面干了什么”,自底向上适合问“谁调用了这个热点”。

5.1 采样与 safepoint bias

JVM 自己的采样(ExecutionSample、hprof CPU 采样)只在 safepoint 取栈,而 safepoint 多落在方法边界、循环回边、调用点。结果是紧凑的无调用循环可能永远采不到,看起来“这方法不耗 CPU”。async-profiler 走 AsyncGetCallTrace,可在非 safepoint 位置取栈,明显缓解该问题;代价是依赖 JVMTI 与信号机制,受限容器里可能要额外放行。


6. jcmd 常用子命令

子命令 作用 是否 STW
VM.flags / VM.system_properties 生效参数与系统属性 否
GC.heap_info 各代/各区占用与容量 否
GC.class_histogram 按类统计实例数与字节数 是(短暂)
Thread.print -l 全线程栈,含锁信息 是(短暂)
VM.metaspace / VM.native_memory Metaspace 明细、NMT(需启动参数) 否
JFR.start / JFR.dump / JFR.stop 事件记录控制 否
$ jcmd 5123 help                    # 完整子命令清单,版本差异以它为准
$ jcmd 5123 GC.class_histogram | head -n 20

7. 排错:工具本身的坑

现象 原因 处理
开 JFR 后 CPU 明显上升 用 profile 常开,或事件阈值过低 换 default,用 maxsize 限容
.jfr 巨大且刷盘频繁 无 maxsize、无 duration 环形缓冲 + 定长窗口
转储文件比 -Xmx 还大 对象图与元数据未压缩,不等于使用量 预留两倍堆以上磁盘
GC.heap_dump 报错或 0 字节 目录无写权限、磁盘满 用同一用户写,先 df -h
火焰图没有热点 用 cpu 但瓶颈在等待 换 wall 再看一遍
只盯分配点,GC 依旧频繁 分配多但对象存活久 看 alloc 存活侧 + 支配树
把最宽的帧当根因 宽帧常是框架入口 Servlet.service 往下钻叶子,或看 inverted

8. 边界:这些工具答不了什么

场景 给不了什么 该补什么
内核态/系统调用占比高 只有 native 栈,缺内核栈 perf、bcc、bpftrace
跨请求因果链 单进程证据,缺上下游 分布式追踪 Trace/Span
长周期趋势与容量规划 只有窗口内快照 指标系统 + 长期存储
堆外内存泄漏 hprof 不含 DirectByteBuffer 实际内存与 JNI 分配 NMT、pmap、malloc 追踪
类加载器泄漏 看到类数增长,看不清加载器图 MAT Duplicate Classes + 加载器链

一句话收口:JFR 定性、jcmd 定量、MAT 定责、async-profiler 定位。四件都上还解释不了的现象,基本都在 JVM 之外。


9. 自测

  1. 一个服务 CPU 图很平、火焰图没有明显热点,但接口 RT 翻倍,下一步换哪种事件采样?
  2. default.jfc 与 profile.jfc 的差别主要落在哪个参数上,为什么低配机器不该用后者常开?
  3. jmap -dump:live 比 jcmd GC.heap_dump 多做了哪件事,代价是什么?
  4. 在 MAT 里看引用链时,为什么要排除弱引用与软引用?
  5. safepoint bias 会让哪一类代码在 ExecutionSample 里“隐身”?
  6. 火焰图上最宽的帧为什么通常不能直接当根因?
S05-X17 · JVM 问题定位工具链:JFR、MAT 与 async-profiler
https://www.clxhxhhr.top/posts/5904/
作者
clxstart
发布于
2024-12-31
许可协议
CC BY-NC-SA 4.0
评论
0 条
还没有评论,先写一条吧。