《Java 高级编程》9.2 性能剖析:JFR、火焰图与热点定位

JMH 告诉你一次调用多快,JFR 告诉你时间花在哪。本节用 JDK 25 内置 Flight Recorder 记录 10 秒 libraryd 负载,执行 jfr summary、jfr view hot-methods 与 jfr print --events jdk.ExecutionSample,引用 156 个采样和 272 MB Overdue 分配,并说明火焰图边界。

本节目标:用 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 的诊断流程可以固定成四步:

  1. 在测试环境用 -XX:StartFlightRecording=filename=/tmp/libraryd.jfr,duration=60s,settings=profile 启动服务,跑一轮借阅压测。
  2. 用 jfr summary 确认记录时长和样本量;样本少于 100 个就延长记录或提高采样率。
  3. 用 jfr view hot-methods 找 CPU 热点,用 allocation-by-site 找分配热点。
  4. 用 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 优化决策:分配、锁与批处理的收益核算 。

继续阅读

探索更多技术文章

浏览归档,发现更多关于系统设计、工具链和工程实践的内容。

全部文章 返回首页

「java」更多文章

  1. 《Netty 高性能网络编程》15.3 linkd-v2 验收与复盘
  2. 《Netty 高性能网络编程》15.2 限流、超时与降级
  3. 《Netty 高性能网络编程》15.1 网关路由与转发