Skip to content

JFR + JMC 生产诊断

先看一个真实案例

2023 年双 11 大促,某支付中台的核心交易服务在高峰时段出现周期性 RT 抖动:TP99 从 15ms 跳到 120ms,每 5 分钟一次,持续 20 秒后恢复。运维先上了 Arthas,发现 Old Gen 使用率在 60%~80% 之间波动,看不出明显异常。又加了 -XX:+HeapDumpOnOutOfMemoryError,但 OOM 没发生,Heap Dump 也没触发。最后用 JFR + JMC 定位到根因:G1 的 Mixed GC 周期中,Remembered Set 扫描时间异常(一次 Mixed GC 的 STW 达到 380ms),原因是某个表的数据量溢出导致 RSet 密度过高,GC 线程花了大量时间扫描跨 Region 引用。用 JFR 的 GC 事件时间线一看,STW 峰值和 RT 抖动完全对齐。最终方案是调大 -XX:G1MixedGCLiveThresholdPercent=85 让 Mixed GC 跳过存活率高的 Region,配合 -XX:G1HeapWastePercent=10 延迟触发,抖动消失。

JFR 的定位能力在这里是其他工具替代不了的:Arthas 看当前线程堆栈,Heap Dump 只有 OOM 才能触发,而 JFR 在常态运行中就能精确记录每一次 GC 事件的时间和耗时时长,事后拉出时间线做关联分析。

JFR 的低开销原理——为什么能跑在生产环境

事件驱动架构(不是采样轮询)

JFR 不走「定时采样」路线,它在 JVM 内部注册了 300+ 个预定义事件点(Event Point),比如 GC 阶段开始/结束、Java Monitor 进入/退出、方法抛异常、TLAB 分配等。这些事件点本身是 JVM 代码里的固定桩,JFR 运行时只做两件事:

  1. 阈值过滤:对每个事件类型设置 Duration 阈值,比如 synchronized 锁等待超过 10ms 才记录,小于 10ms 的直接丢弃。这避免了记录大量无害的短锁竞争。
  2. 无锁写入 Ring Buffer:事件数据写入线程本地的 TLAB 风格缓冲区,满了再刷到全局 Ring Buffer,全程无锁。Ring Buffer 的默认大小是 4MB(-XX:FlightRecorderBufferSize=4m),写满后会覆盖最旧的数据,所以 JFR 不会因为内存不够而 OOM。

对比采样工具(如 async-profiler 的 CPU 采样模式,每 10ms 打断一次线程),JFR 在 CPU 总量上更可控,尤其在 1000+ 线程的场景下,JFR 的 CPU 开销稳定在 0.5-1% 左右,而 async-profiler 的采样中断在超高线程数下会达到 3-5%。

二进制格式——不经过堆内存

JFR 的输出格式 .jfr 是自描述二进制流,写入路径直接从 Ring Buffer 写入文件系统,完全不经过 Java 堆。这意味着:

  • 不会触发 GC 停顿
  • 不会因为 Full GC 丢了录制数据
  • 文件体积极小:1 小时 default 模板约 30-50MB,profile 模板约 100-200MB

对比 Heap Dump 在 OOM 时写十几 GB 文件把容器撑爆,JFR 的存储开销几乎可以忽略。

命令行操作流程

bash
# 1. 启动时开启 JFR(JDK 8u40+,JDK 11+ 内置)
java -XX:StartFlightRecording=name=production,filename=recording.jfr,duration=60s,settings=profile \
     -jar myapp.jar

# 2. 运行时动态开启(推荐,生产环境用这个)
jcmd <pid> JFR.start name=myrecording settings=profile duration=60s filename=/tmp/recording.jfr

# 3. 另存为(不停止录制)
jcmd <pid> JFR.dump name=myrecording filename=/tmp/dump-$(date +%s).jfr

# 4. 停止并写出
jcmd <pid> JFR.stop name=myrecording

# 5. 查看当前录制状态
jcmd <pid> JFR.check

# 输出示例:
# Recording: name=myrecording, duration=60s, recording=15s (running)
# Settings: profile, maxsize=250MB, maxage=30m

jcmd <pid> JFR.check 在没有 JMC 的容器里也能快速确认录制是否正常,是排查 JFR 本身问题的第一手工具。

用 JFR 分析 GC 和锁竞争的实战流程

GC 分析——定位 STW 抖动

在 JMC 中打开 .jfr 文件,切到 Flight Recorder → GC 标签页,你会看到以下信息:

指标含义正常值告警阈值
GC Pause Time每次 STW 时长G1 下 < 50ms> 200ms
GC Interval两次 GC 间隔30-120s< 5s
GC Cause触发原因G1 Evacuation PauseSystem.gc()
Promotion Failed晋升失败次数0> 0
Concurrent Mode Failure并发标记失败0> 0

典型案例:某营销系统在整点发券时,G1 的 Young GC 耗时从 30ms 飙升到 250ms。JFR 显示触发原因是 G1 Evacuation Pause (to-space exhausted),说明 Survivor 区太小,对象晋升失败被迫 Full GC。调参 -XX:SurvivorRatio=6-XX:G1NewSizePercent=10 后,GC 耗时回到 35ms。

锁竞争分析——找到热点锁

JMC 的 Lock Instances 标签页展示每个锁的竞争情况。关键指标:

  • Total Contentions:锁上的总竞争次数
  • Total Wait Time:所有线程等待这个锁的总耗时
  • Average Wait Time:平均每次等待时间
  • Contended Lock Class:锁的对象类型

实战案例:某订单服务 TP99 从 30ms 涨到 200ms。JFR 显示 java.util.concurrent.ConcurrentHashMapresize 方法上出现大量锁竞争,总等待时间占到了 RT 的 42%。排查发现某个热点缓存 Key 的 Hash 碰撞导致 ConcurrentHashMap 频繁扩容。改成 HashMap + 读写锁 后,TP99 降到 28ms。

java
// 用 jdk.jfr API 自定义事件(JDK 14+)
import jdk.jfr.*;

@Label("DB Query")
@Description("Track slow database queries")
@Category({"Application", "Database"})
public class DBQueryEvent extends Event {
    @Label("SQL")
    public String sql;

    @Label("Duration (ms)")
    @Timespan(Timespan.MILLISECONDS)
    public long durationMs;

    @Label("Result Size")
    public int resultSize;

    @Label("Pool Name")
    public String poolName;
}

// 使用
DBQueryEvent event = new DBQueryEvent();
event.sql = query;
event.poolName = "readPool";
event.begin();
try {
    List<Order> result = jdbcTemplate.query(query, mapper);
    event.resultSize = result.size();
    return result;
} finally {
    event.commit();
}

注意:自定义 Event 的 begin()commit() 必须成对调用,漏写 commit() 会导致事件丢失,且 JFR 不会报错,只能通过 jcmd <pid> JFR.check 看 Event 总数来确认是否正常记录。

生产环境常态开启的实践

轮转录制方案

bash
# 持续录制,每 2 小时写一个文件,保留最近 3 个文件
jcmd <pid> JFR.start name=continuous \
    settings=default \
    maxage=2h \
    maxsize=500m

# 告警触发时 dump 当前录制到持久存储
jcmd <pid> JFR.dump name=continuous \
    filename=/data/jfr/alert-$(date +%s).jfr

# 定时任务:压缩并归档旧文件
# 0 * * * * find /data/jfr -name "*.jfr" -mtime +7 -delete

模板选择

模板开销记录粒度适用场景
default0.3-0.5%只记录关键事件常态开启,7×24
profile1-2%更细粒度,包括方法采样定位阶段,1-2 小时
自定义可控只开需要的事件针对特定问题

自定义模板文件(JFC 格式)放在 $JAVA_HOME/lib/jfr/ 下,也可以用 jcmd <pid> JFR.configure 在线修改部分参数。

远程触发(JDK 16+ 的 JMX 支持)

java
// 通过 JMX 远程触发 JFR dump
MBeanServerConnection conn = ...;
ObjectName jfrBean = new ObjectName("jdk.management.jfr:type=FlightRecorder");
String[] signature = new String[] { String.class.getName() };
Object[] params = new Object[] { "continuous" };
conn.invoke(jfrBean, "dumpRecording", params, signature);

配合 Prometheus AlertManager 的 Webhook,可以在 CPU 飙高或 GC 停顿超过阈值时自动 dump JFR 并上传到 OSS。

常见踩坑

  1. JFR 本身被禁用了:部分 JDK 8 发行版(如某些 OpenJDK 构建)不包含 JFR。JDK 11+ 全部内置,JDK 8 需要确认是 Oracle JDK 或 Zulu JDK 等商业构建。
  2. maxagemaxsize 同时设置:JFR 会取二者中先到达的限制。如果 maxage=2hmaxsize=100m,写入速度快的应用可能在 10 分钟内就触发了 maxsize 覆盖,导致 2 小时内的事件被提前丢弃。
  3. 容器内存限制:JFR 的 Ring Buffer 默认 4MB 虽然小,但如果容器配置了 -XX:MaxRAMPercentage=70 且堆外内存不足,JFR 的写入线程可能被 OOM Killer 杀死。建议容器环境给 JFR 预留 64MB 堆外内存(-XX:MaxDirectMemorySize=64m)。
  4. JMC 版本不匹配:JDK 17 的 JFR 文件格式和 JDK 11 不完全兼容,用旧版 JMC 打开新版 JFR 会报 Unsupported magic number。JMC 9.x 兼容 JDK 11-21,JMC 8.x 兼容 JDK 8-17。

总结

  • JFR 生产开销 < 1%,基于事件驱动 + 环形缓冲区,不经过堆,不触发 GC
  • jcmd <pid> JFR.start 可动态开启/停止/转储,无需重启,命令行和 JMX 双通道可用
  • JMC 是 JFR 的可视化分析工具,GC 标签页看 STW 时间线,Lock Instances 标签页看锁竞争
  • 自定义 Event 可以埋点业务代码,用 jdk.jfr.Event API 自动管理时间,但注意 begin/commit 配对
  • 生产实践:常态开启 default 轮转录制 + 告警触发 dump + 归档,避免事后追查空手而归
  • 重要:JFR 是"常态武器"不是"事后急救",先开起来,等出问题才有数据

参考

  • JDK 官方文档 — Java Flight Recorder (JFR) — oracle.com
  • JDK 源码 — jdk.jfr.Event
  • JMC 用户指南 — openjdk.org
  • JFR 自定义事件模板 — Baeldung Guide to JFR
  • 《Java Performance: The Definitive Guide》— Scott Oaks

手撕 → 框架 → 生产化,一步步把 AI Agent 工程化搞透。