线上变慢时,最顺手的动作是“挂个 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. 自测
- 一个服务 CPU 图很平、火焰图没有明显热点,但接口 RT 翻倍,下一步换哪种事件采样?
default.jfc与profile.jfc的差别主要落在哪个参数上,为什么低配机器不该用后者常开?jmap -dump:live比jcmd GC.heap_dump多做了哪件事,代价是什么?- 在 MAT 里看引用链时,为什么要排除弱引用与软引用?
- safepoint bias 会让哪一类代码在
ExecutionSample里“隐身”? - 火焰图上最宽的帧为什么通常不能直接当根因?