本节目标:用 JDK 自带的 Flight Recorder 记录一段真实负载,从
jfr summary、jfr view hot-methods、jfr print和分配采样里定位热点,并知道什么时候需要火焰图、什么时候 JFR 已经够用。
适用版本:JDK 25(Temurin 25.0.5)。JFR 在 JDK 11 起开源并内置;jfr命令行工具随 JDK 发布;本机未安装 async-profiler。
承接的问题
9.1 的 JMH 结果显示 Loan.state 大约 2 ns/op,FinePolicyBenchmark 的四种写法差距在误差范围内。这个结论只回答了「单次调用多快」,没有回答下面这些生产问题:
- 12 秒的借阅批处理里,CPU 时间到底花在
Loan.state、ISBN 校验,还是Thread.sleep? LoanState.Overdue到底分配了多少?GC 压力是不是来自这里?- 代码里明明有
isbnChecksum,为什么采样里看不到它? - 火焰图上最宽的那一块,对应哪个方法?
回答这些问题需要采样剖析器。JFR 是 JDK 内置的,不需要额外安装 agent,不需要改代码,开销可控,适合在测试环境和生产环境短时间开启。它的数据模型是「事件」:jdk.ExecutionSample 记录线程栈采样,jdk.ObjectAllocationSample 记录分配采样,jdk.GCPhasePause 记录 GC 停顿,等等。
先用一个可复现的负载把 JFR 跑通,再讨论怎么读。
核心机制一:开启一次有边界的记录
被剖析的负载是 LibraryLoad:
package com.plume.library.load;
import com.plume.library.domain.Loan;
import com.plume.library.domain.LoanState;
import java.time.LocalDate;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.TimeUnit;
public final class LibraryLoad {
private static final LocalDate TODAY = LocalDate.of(2026, 11, 10);
private static final long NANOS_PER_SECOND = TimeUnit.SECONDS.toNanos(1);
public static void main(String[] args) throws Exception {
List<Loan> loans = new ArrayList<>();
for (int i = 0; i < 2_000; i++) {
LocalDate dueOn = TODAY.minusDays(i % 40).plusDays(7);
loans.add(new Loan(i, "97801346859" + (i % 10), "m-" + i,
dueOn.minusDays(Loan.LOAN_DAYS), dueOn, null, 0));
}
long deadline = System.nanoTime() + 12 * NANOS_PER_SECOND;
long checksum = 0;
long rounds = 0;
while (System.nanoTime() < deadline) {
for (Loan loan : loans) {
checksum += fineOf(loan);
checksum += isbnChecksum(loan.isbn());
}
rounds++;
Thread.sleep(1);
}
System.out.println("rounds=" + rounds + " checksum=" + checksum);
}
private static long fineOf(Loan loan) {
return switch (loan.state(TODAY)) {
case LoanState.Active active -> 0L;
case LoanState.Overdue overdue -> overdue.days() * Loan.FINE_CENTS_PER_DAY;
case LoanState.Returned returned -> returned.fineCents();
};
}
private static int isbnChecksum(String digits12) {
int sum = 0;
for (int i = 0; i < 12; i++) {
int digit = digits12.charAt(i) - '0';
sum += (i % 2 == 0) ? digit : digit * 3;
}
return (10 - (sum % 10)) % 10;
}
}
这个负载每轮处理 2000 个 loan,每个 loan 调一次 fineOf 和一次 isbnChecksum,轮间 sleep(1) 毫秒。它比 JMH 的紧循环更接近批处理任务:有数组遍历、有方法调用、有短暂的阻塞。
记录命令:
java -XX:StartFlightRecording=filename=/tmp/vol3-c/jfr/libraryd.jfr,duration=10s,settings=profile \
-cp out com.plume.library.load.LibraryLoad
本机启动输出:
[0.264s][info][jfr,startup] Started recording 1. The result will be written to:
[0.264s][info][jfr,startup]
[0.264s][info][jfr,startup] /tmp/vol3-c/jfr/libraryd.jfr
rounds=9142 checksum=12149718000
记录文件 377 KB。三个参数的作用:
filename指定落盘路径。不写的话,记录只存在内存里,需要jcmd或 JMC 导出。duration=10s让记录在 10 秒后自动停止。负载跑了 12 秒,保证记录覆盖完整的稳态阶段,又不会无限增长。settings=profile使用更密集的采样配置,适合短时间诊断。默认配置开销更低,适合长时间开启;profile的采样率更高,开销也更大。
对已经在运行的进程,用 jcmd 开启:
jcmd <pid> JFR.start name=libraryd-profile \
filename=/tmp/libraryd.jfr duration=30s settings=profile
jcmd <pid> JFR.dump name=libraryd-profile filename=/tmp/libraryd.jfr
jcmd <pid> JFR.stop name=libraryd-profile
JFR.start 是异步的,命令返回不代表记录完成;JFR.dump 可以在记录结束前导出当前内容。容器里要确认 /tmp 有空间,并且记录文件会被复制出来;Pod 重启后文件就没了。
核心机制二:jfr summary 看事件全貌
jfr summary /tmp/vol3-c/jfr/libraryd.jfr
本机输出摘录:
Version: 2.1
Chunks: 1
Start: 2026-10-28 02:14:51 (UTC)
Duration: 10 s
Event Type Count Size (bytes)
=============================================================
jdk.NativeLibrary 846 73033
jdk.SystemProcess 798 84743
jdk.GCPhaseParallel 632 15531
jdk.ModuleExport 511 5500
jdk.BooleanFlag 485 14402
jdk.ActiveSetting 376 9324
jdk.ObjectAllocationSample 316 4433
jdk.ExecutionSample 156 1560
jdk.ModuleRequire 156 1560
jdk.LongFlag 138 4295
jdk.PromoteObjectInNewPLAB 110 1888
jdk.UnsignedLongFlag 93 3054
jdk.InitialEnvironmentVariable 61 3555
jdk.Checkpoint 43 39399
...
先看三个数:
Duration: 10 s确认记录窗口正确。如果只有 0.1 秒,样本量不够,结论不可信。jdk.ExecutionSample 156是 CPU 采样事件数。10 秒 156 个样本,大约每 64 毫秒一个;样本越少,热点排序的噪声越大。jdk.ObjectAllocationSample 316是分配采样事件数。JFR 按 TLAB 分配采样,不是每次new都记录;它给出的是「分配压力」的估计,不是精确字节数。
jdk.NativeLibrary、jdk.SystemProcess、jdk.ModuleExport 这些事件是 JVM 启动和模块系统的元数据,不是性能热点。读 summary 时不要被数量最多的行带偏;先找 ExecutionSample、ObjectAllocationSample、GCPhasePause、JavaMonitorEnter 这几类。
核心机制三:jfr view 直接给出热点方法
JDK 25 的 jfr 自带 view 子命令,不需要 JMC 就能看常用视图:
jfr view hot-methods /tmp/vol3-c/jfr/libraryd.jfr
本机输出:
Java Methods that Execute the Most
Method Samples Percent
--------------------------------------------------------------- ------- -------
com.plume.library.domain.Loan.state(LocalDate) 116 74.36%
com.plume.library.load.LibraryLoad.main(String[]) 26 16.67%
java.lang.Thread.sleep(long) 11 7.05%
jdk.internal.event.ThreadSleepEvent.isEnabled() 1 0.64%
jdk.internal.event.ThreadSleepEvent.commit() 1 0.64%
java.lang.Thread.sleepNanos(long) 1 0.64%
Loan.state 占了 74.36% 的样本,是明确的第一热点。main 的 16.67% 包含循环控制、isbnChecksum 和 fineOf 的内联代码;Thread.sleep 的 7.05% 是轮间等待,不是 CPU 热点,但在采样里会占一部分。
这张表回答了两个问题:热点在 Loan.state,不在 ISBN 校验;sleep 占了一小部分,说明负载不是纯 CPU 忙等。它没有回答「Loan.state 内部哪一行慢」,那需要更细的栈或 JIT 编译日志。
jfr view 还有别的视图:
jfr view allocation-by-class /tmp/vol3-c/jfr/libraryd.jfr
jfr view allocation-by-site /tmp/vol3-c/jfr/libraryd.jfr
jfr view gc-configuration /tmp/vol3-c/jfr/libraryd.jfr
allocation-by-class 按对象类型聚合分配压力,allocation-by-site 按分配发生的方法聚合。后者对定位「谁在 new」更有用。
核心机制四:jfr print 看原始栈
jfr view 是聚合视图,看不到单次采样的完整栈。需要原始事件时用:
jfr print --events jdk.ExecutionSample /tmp/vol3-c/jfr/libraryd.jfr | head -40
本机输出摘录:
jdk.ExecutionSample {
startTime = 10:14:51.801 (2026-10-28)
sampledThread = "main" (javaThreadId = 3)
state = "STATE_RUNNABLE"
stackTrace = [
jdk.internal.event.ThreadSleepEvent.isEnabled()
jdk.internal.event.ThreadSleepEvent.commit()
java.lang.Thread.afterSleep(ThreadSleepEvent) line: 492
java.lang.Thread.sleepNanos(long) line: 512
java.lang.Thread.sleep(long) line: 540
...
]
}
jdk.ExecutionSample {
startTime = 10:14:51.881 (2026-10-28)
sampledThread = "main" (javaThreadId = 3)
state = "STATE_RUNNABLE"
stackTrace = [
com.plume.library.domain.Loan.state(LocalDate) line: 29
com.plume.library.load.LibraryLoad.fineOf(Loan) line: 39
com.plume.library.load.LibraryLoad.main(String[]) line: 29
]
}
第二个样本的栈很清楚:main 调用 fineOf,fineOf 调用 Loan.state,采样落在 state 的第 29 行。第一个样本落在 Thread.sleep,是轮间等待。
jfr print 的输出适合人工抽查,不适合直接统计几百个样本。要聚合,可以用 --json 导出再写脚本:
jfr print --json --events jdk.ExecutionSample libraryd.jfr > samples.json
本机用 Python 统计栈顶帧,得到和 jfr view 一致的结果:156 个样本里 116 个栈顶是 Loan.state,26 个是 main,11 个是 Thread.sleep。脚本不需要第三方库,json 加 collections.Counter 就够。
一个重要现象:isbnChecksum 没有出现在热点表里。它不是没执行,而是被 JIT 内联进了 main,采样栈里看不到独立帧。JFR 记录的是「采样时刻的 Java 栈」,内联后的方法不会单独出现。看到某个方法「消失」时,先查 JIT 编译日志或 -XX:+PrintInlining,不要直接判断它没被调用。
核心机制五:分配采样与火焰图
分配视图:
jfr view allocation-by-class /tmp/vol3-c/jfr/libraryd.jfr
本机输出:
Allocation by Class
Object Type Allocation Pressure
----------------------------------------------------------- -------------------
com.plume.library.domain.LoanState$Overdue 79.39%
com.plume.library.domain.LoanState$Active 15.93%
com.plume.library.domain.Loan 4.65%
java.util.ArrayList$Itr 0.03%
allocation-by-site:
Allocation by Site
Method Allocation Pressure
----------------------------------------------------------- -------------------
com.plume.library.domain.Loan.state(LocalDate) 95.32%
com.plume.library.load.LibraryLoad.main(String[]) 4.65%
java.util.ArrayList.iterator() 0.03%
Loan.state 贡献了 95.32% 的分配压力,其中 Overdue 占 79.39%。这和代码一致:每轮 2000 个 loan,大部分处于逾期状态,每次调用 state 都 new LoanState.Overdue(dueOn, days)。本机 JFR 估计 10 秒内 Overdue 分配了约 272 MB,Active 约 54 MB。这个数字不是精确的堆增长,因为采样有权重和外推;但量级足够说明「分配热点在 state,不在 ISBN 校验」。
火焰图有两种常见做法:
- JDK Mission Control 打开
.jfr,选择「Method Profiling」或「Flame View」,按栈聚合,宽度表示样本占比。JMC 还能看分配火焰图、锁竞争、GC 停顿。 - 用
jfr print --json导出jdk.ExecutionSample,把每个栈反转成frame1;frame2;... 1的折叠格式,再交给 FlameGraph 脚本或speedscope。这条路径不需要 JMC,适合服务器上只有命令行的情况。
本机没有安装 async-profiler,asprof 不在 PATH 里,因此本节不提供 async-profiler 的实测命令。它适合需要更高采样率、更细分配跟踪或 native 栈的场景;JFR 的 settings=profile 在大多数 Java 热点定位上已经够用。选择工具时先看「已有数据能不能回答问题」,不要为了工具而换工具。
在 libraryd 里落地:把 JFR 变成一次可复现的诊断
libraryd 的诊断流程可以固定成四步:
- 在测试环境用
-XX:StartFlightRecording=filename=/tmp/libraryd.jfr,duration=60s,settings=profile启动服务,跑一轮借阅压测。 - 用
jfr summary确认记录时长和样本量;样本少于 100 个就延长记录或提高采样率。 - 用
jfr view hot-methods找 CPU 热点,用allocation-by-site找分配热点。 - 用
jfr print --events jdk.ExecutionSample抽查 5 到 10 个栈,确认聚合结果和代码路径一致。
JFR 也可以按需开启,不必重启:
jcmd $(pgrep -f libraryd-app) JFR.start \
name=incident-42 filename=/tmp/incident-42.jfr duration=120s settings=profile
线上开启前要确认三件事:磁盘空间足够、记录文件路径可写、采样开销在可接受范围。settings=profile 的采样率比默认高,长时间开启会增加 CPU 和 I/O;诊断结束后用 JFR.stop 停掉,不要让它一直跑。
JFR 记录里可能包含类名、方法名、线程名、部分异常消息和 SQL 文本。把文件带出生产环境前,按公司的数据分类规则检查;不要直接把原始 JFR 贴到公开 issue 里。
常见错误与边界
错误一:记录时间太短。 10 秒只有 156 个 CPU 样本,热点排序的置信度有限;如果记录 1 秒,可能只有十几个样本,Loan.state 和 main 的排序会随机波动。至少记录到「样本量过百」,再做结论。
错误二:把 Thread.sleep 当成 CPU 热点。 采样落在 sleep 上,说明线程当时在等待,不消耗 CPU。火焰图里 sleep 的宽度代表墙钟时间占比,不是 CPU 占比。分析 CPU 热点时先看 STATE_RUNNABLE 的样本,或者用 jfr view hot-methods 的方法排序。
错误三:以为采样能精确到行。 Loan.state 的第 29 行是 ChronoUnit.DAYS.between,但采样只告诉你「当时在这个方法里」,行号受 JIT 优化和调试信息影响。要精确到指令,需要 JIT 编译日志、-XX:+PrintAssembly 或 async-profiler 的 perf 模式,JFR 不负责这个粒度。
错误四:把分配压力当成精确内存占用。 jdk.ObjectAllocationSample 是采样加权重的外推,不是每次 new 的计数。79.39% 说明「大部分分配压力来自 Overdue」,不说明「堆里现在有 272 MB Overdue」。要看实时堆占用,用 jcmd GC.heap_info 或堆转储。
错误五:在容器里把 JFR 文件写到临时层。 Pod 重启后 /tmp 消失,记录文件也跟着消失。把 filename 指到挂载卷,或者在 JFR.stop 后立刻复制出来。CI 里跑 JFR 也要把文件作为 artifact 上传。
边界一:JFR 不是万能的。 它擅长 Java 方法采样、分配、GC、锁、线程状态;对 native 栈、内核态、外部进程的可见性有限。native 崩溃用 hs_err_pid.log,系统级 CPU 用 perf,JFR 只看 JVM 内部。
边界二:内联会隐藏方法。 isbnChecksum 被内联进 main,Loan.state 也可能在别的基准里被内联。热点表里看不到某个方法,不等于它没执行。要确认内联,用 -XX:+UnlockDiagnosticVMOptions -XX:+PrintInlining,或者看 JIT 编译日志。
小结
- JFR 是 JDK 内置的采样剖析器,
-XX:StartFlightRecording可以在启动时记录,jcmd JFR.start可以对运行中的进程按需开启。 jfr summary先确认记录时长和样本量;jdk.ExecutionSample和jdk.ObjectAllocationSample是性能分析最常用的两类事件。jfr view hot-methods在本机把 74.36% 的样本定位到Loan.state;allocation-by-site把 95.32% 的分配压力定位到同一个方法。jfr print --events jdk.ExecutionSample用来抽查原始栈;Thread.sleep的样本是等待,不是 CPU 热点。- 分配视图显示
LoanState.Overdue占 79.39% 的分配压力,10 秒约 272 MB;这是 9.3 讨论分配优化的直接依据。 - 火焰图优先用 JMC 或
jfr print --json加折叠栈;本机未安装 async-profiler,不作实测结论。 - JFR 看不到 native 栈和内联方法,定位到方法后还要结合代码、JIT 日志和基准测试确认。
JFR 给出了三个候选优化点:Loan.state 的分配、计数器的锁竞争、批处理的循环形态。下一节不急着改代码,先把每个候选的收益、成本和回归方法算清楚,再决定动哪一个。
阅读导航:上一节:9.1 基准测试:JMH 的正确用法与常见陷阱 · 下一节:9.3 优化决策:分配、锁与批处理的收益核算 。
继续阅读
探索更多技术文章
浏览归档,发现更多关于系统设计、工具链和工程实践的内容。