JEP 520：JFR 方法计时与跟踪
JEP 520：JFR 方法计时与跟踪
原文：JEP 520- JFR Method Timing & Tracing
作者：
日期：2025-10-26
| 负责人 | 埃里克·加林（Erik Gahlin） |
|---|---|
| 类型 | 特性 |
| 范围 | JDK |
| 状态 | 已关闭 / 已交付 |
| 版本 | 25 |
| 组件 | hotspot/jfr |
| 讨论组 | hotspot - jfr - dev@openjdk.org |
| 工作量 | S |
| 时长 | S |
| 评审人 | 马库斯·格伦隆德（Markus Grönlund）、弗拉基米尔·科兹洛夫（Vladimir Kozlov） |
| 批准人 | 弗拉基米尔·科兹洛夫（Vladimir Kozlov） |
| 创建时间 | 2024/03/20 14:10 |
| 更新时间 | 2025/07/11 19:51 |
| 问题编号 | 8328610 |
摘要
通过 字节码插装，为 JDK 飞行记录器（JFR）添加方法计时和跟踪功能。
目标
- 对于方法调用，记录完整且精确的统计信息，而非不完整且不精确的基于采样的统计信息。
- 允许在无需修改源代码的情况下，记录特定方法的执行时间和堆栈跟踪信息。
- 允许通过命令行参数、配置文件、
jcmd工具 以及通过 Java 管理扩展 API（JMX）在网络上选择要跟踪的方法。
非目标
- 记录方法参数或非静态字段的值并非本特性的目标。
- 对没有字节码表示的方法（如抽象方法、本地方法或非静态非默认接口方法）进行计时或跟踪并非本特性的目标。
- 同时对大量方法进行计时或跟踪并非本特性的目标，因为这会显著降低性能。在这种情况下应使用方法采样。
- JFR 通常旨在将 CPU 开销控制在 1% 以内。在对方法进行计时和跟踪时，并不以满足这一限制为目标。
动机
对方法调用进行计时和跟踪有助于识别性能瓶颈、优化代码以及查找错误的根本原因。例如，如果一个应用程序启动时间异常长，跟踪静态初始化器可以揭示哪些类加载可以推迟到后期进行。如果为修复性能问题而修改了一个方法，对其执行进行计时可以确认修复是否成功。如果一个应用程序因耗尽数据库连接而失败，跟踪打开连接的方法可以为更有效地管理这些连接提供思路。
在开发过程中，我们已经拥有用于分析方法执行的优秀工具：Java 微基准测试工具包（JMH）可以测量方法执行时间，基于 Java 调试接口（JDI）构建的调试器可以设置断点并检查调用堆栈。
然而，在测试和生产阶段，方法计时和跟踪面临一些挑战。目前有几种方法，但都不尽人意：
- 在被调查的方法中添加临时日志语句或 JFR 事件。这充其量只是麻烦，对于第三方库或 JDK 中的类来说并不可行。
- 使用基于采样的分析器，如 JFR 内置的分析器 或像 async-profiler 这样的第三方工具。这些工具可以捕获频繁执行方法的堆栈跟踪信息，但无法对每次调用进行计时和跟踪。
- 使用 Java 代理，如 JDK 任务控制工具 所使用的代理，对方法进行插装以发出 JFR 事件。虽然这种方法可行，但在 JDK 内部进行此类插装会带来性能优势。例如，JVM 可以过滤方法，无需对每个加载的类的字节码进行两次解析。在 JDK 中提供此特性还将简化使用，因为无需配置或安装代理即可对方法进行计时和跟踪。
JDK 应该提供一种低开销的方法来对方法调用进行计时和跟踪，使开发人员能够轻松高效地分析和优化他们的应用程序。
描述
我们引入两个新的 JFR 事件：jdk.MethodTiming 和 jdk.MethodTrace。它们都接受一个过滤器，用于选择要计时和跟踪的方法。
例如，要查看是什么触发了 HashMap 的扩容，可以在进行记录时配置 MethodTrace 事件的过滤器，然后使用 jfr 工具 显示记录的事件：
$ java -XX:StartFlightRecording:jdk.MethodTrace#filter=java.util.HashMap::resize,filename=recording.jfr ...
$ jfr print --events jdk.MethodTrace --stack-depth 20 recording.jfr
jdk.MethodTrace {
startTime = 00:39:26.379 (2025-03-05)
duration = 0.00113 ms
method = java.util.HashMap.resize()
eventThread = "main" (javaThreadId = 3)
stackTrace = [
java.util.HashMap.putVal(int, Object, Object, boolean, boolean) line: 636
java.util.HashMap.put(Object, Object) line: 619
sun.awt.AppContext.put(Object, Object) line: 598
sun.awt.AppContext.<init>(ThreadGroup) line: 240
sun.awt.SunToolkit.createNewAppContext(ThreadGroup) line: 282
sun.awt.AppContext.initMainAppContext() line: 260
sun.awt.AppContext.getAppContext() line: 295
sun.awt.SunToolkit.getSystemEventQueueImplPP() line: 1024
sun.awt.SunToolkit.getSystemEventQueueImpl() line: 1019
java.awt.Toolkit.getEventQueue() line: 1375
java.awt.EventQueue.invokeLater(Runnable) line: 1257
javax.swing.SwingUtilities.invokeLater(Runnable) line: 1415
java2d.J2Ddemo.main(String[]) line: 674
]
}
$
过滤器指定为 java.util.HashMap::resize，就像源代码中的 方法引用 一样。在 JVM 启动时，它会通过注入字节码来插装这个方法，以发出 MethodTrace 事件。
通过配置文件使用
在实际应用中，JFR 通常通过配置文件进行配置，而非在命令行中显式提及事件。JDK 包含两个配置文件：default.jfc 和 profile.jfc。前者在未指定配置文件时使用，后者包含方便进行性能分析的配置设置。这些文件可以声明在启动 JVM 时可在命令行中给出的选项，或者在已运行的 JVM 上通过 jcmd 给出。
我们在 default.jfc 和 profile.jfc 中添加两个新选项：method-timing 和 method-trace，它们分别控制 MethodTiming 和 MethodTrace 事件的过滤器设置。method-timing 选项统计匹配过滤器的方法的调用次数，并计算其平均执行时间；method-trace 选项记录匹配过滤器的方法的堆栈跟踪信息。
此外，我们增强了 jfr view 和 jcmd <pid> JFR.view 命令，以显示方法计时和跟踪结果。
综上所述，如果一个应用程序启动缓慢，对所有静态初始化器的执行进行计时，可能会提示哪些地方可以使用延迟初始化。我们可以通过省略类名，指定 ::<clinit> 作为过滤器，来对所有类中的所有静态初始化器进行计时：
$ java '-XX:StartFlightRecording:method-timing=::<clinit>,filename=clinit.jfr' ...
$ jfr view method-timing clinit.jfr
Method Timing
Timed Method Invocations Average Time
------------------------------------------------------ ----------- ------------
sun.font.HBShaper.<clinit>() 1 32.500000 ms
java.awt.GraphicsEnvironment$LocalGE.<clinit>() 1 32.400000 ms
java2d.DemoFonts.<clinit>() 1 21.200000 ms
java.nio.file.TempFileHelper.<clinit>() 1 17.100000 ms
sun.security.util.SecurityProviderConstants.<clinit>() 1 9.860000 ms
java.awt.Component.<clinit>() 1 9.120000 ms
sun.font.SunFontManager.<clinit>() 1 8.350000 ms
sun.java2d.SurfaceData.<clinit>() 1 8.300000 ms
java.security.Security.<clinit>() 1 8.020000 ms
sun.security.util.KnownOIDs.<clinit>() 1 7.550000 ms
...
$
基于类和注解的过滤
除了方法，过滤器还可以指定一个类，在这种情况下，该类中的所有方法都会被计时或跟踪。
过滤器也可以指定一个注解。这会导致所有带有该注解的方法，以及所有带有该注解的类中的所有方法，都会被计时或跟踪。例如，要查看 Jakarta REST 端点被调用的次数，并测量大致的执行时间：
$ jcmd <pid> JFR.start method-timing=@jakarta.ws.rs.GET
你可以指定多个过滤器，用分号分隔。例如，我们可以通过跟踪文件描述符的创建和销毁，并查找不匹配的事件，来找出文件描述符在哪里发生泄漏：
$ java '-XX:StartFlightRecording:filename=fd.jfr,method-trace=java.io.FileDescriptor::<init>;java.io.FileDescriptor::close' ...
$ jfr view --cell - height 5 MethodTrace fd.jfr
Method Trace
Start Time Duration Event Thread Stack Trace Method
---------- ----------- ---------------- ----------------------------------------------- -------------------------------
20:32:39 0.000542 ms AWT - EventQueue - 0 java.io.FileInputStream.<init>(File) java.io.FileDescriptor.<init>()
sun.security.provider.FileInputStreamPool.ge...
sun.security.provider.NativePRNG$RandomIO.<i...
sun.security.provider.NativePRNG.initIO(...)
sun.security.provider.NativePRNG.<clinit>()
20:32:39 0.000334 ms AWT - EventQueue - 0 java.io.FileInputStream.<init>(File) java.io.FileDescriptor.<init>()
java.io.FileInputStream.<init>(String)
sun.awt.FontConfiguration.readFontConfigFile...
sun.awt.FontConfiguration.init()
sun.font.CFontManager.createFontConfiguration()
20:32:39 0.0166 ms AWT - EventQueue - 0 java.io.FileInputStream$1.close() java.io.FileDescriptor.close()
java.io.FileDescriptor.closeAll(Closeable)
java.io.FileInputStream.close()
sun.awt.FontConfiguration.readFontConfigFile...
sun.awt.FontConfiguration.init()
...
$
--cell - height 选项设置为一个事件显示的最大行数。在这个例子中，它设置了每个堆栈跟踪显示的最大帧数。
过滤器语法
总体而言，过滤器的语法如下：
filter ::= target (";" target)*
target ::= class | class-method | method | annotation
class ::= identifier ("." identifier)*
class-method ::= class method
method ::= "::" method-name
method-name ::= identifier | "<clinit>" | "<init>"
annotation ::= "@" class
identifier ::= 见 JLS §3.8
方法名为 <init> 的过滤器会匹配指定类的所有构造函数，就像 <clinit> 匹配类的静态初始化器一样。
当指定的方法名是 重载 的时，过滤器会匹配多个方法，在这种情况下，JFR 会插装指定类中所有该名称的方法。
自定义配置文件
如果你需要对多个方法进行计时或跟踪，可以创建一个单独的配置文件来列出所有方法：
<?xml version="1.0" encoding="UTF-8"?>
<configuration version="2.0">
<event name="jdk.MethodTiming">
<setting name="enabled">true</setting>
<setting name="filter">
com.example.Foo::method1;
com.example.Bar::method2;
...
com.example.Baz::method17
</setting>
</event>
</configuration>
然后你可以将其与默认配置结合使用：
$ java -XX:StartFlightRecording:settings=timing.jfc,settings=default ...
自定义注解
定义自定义注解来标记方法或类，以便日后调查，这会很方便。例如：
package com.example;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
import static java.lang.annotation.ElementType.METHOD;
import static java.lang.annotation.ElementType.TYPE;
@Retention(RUNTIME)
@Target({ TYPE, METHOD })
public @interface StopWatch {
}
@Retention(RUNTIME)
@Target({ TYPE, METHOD })
public @interface Initialization {
}
@Retention(RUNTIME)
@Target({ TYPE, METHOD })
public @interface Debug {
}
当你需要对应用程序进行故障排除时，可以指定适当的注解来进行计时或跟踪：
$ java -XX:StartFlightRecording:method-trace=@com.example.Debug ...
$ java -XX:StartFlightRecording:method-timing=@com.example.Initialization,@com.example.StopWatch ...
你可以将生成的 MethodTiming 和 MethodTrace 事件与 JFR 发出的其他事件（如锁争用、方法采样或 I/O 事件）关联起来，以确定程序中带注解部分运行缓慢的原因。
远程配置
你可以使用 JMX 和 JFR 的 RemoteRecordingStream 类通过网络配置计时和跟踪。例如：
import javax.management.remote.*;
import jdk.management.jfr.*;
// 建立与远程主机的非安全连接
var url = "service:jmx:rmi:///jndi/rmi://example.com:7091/jmxrmi";
var jmxURL = new JMXServiceURL(url);
try (var conn = JMXConnectorFactory.connect(jmxURL)) {
try (var r = new RemoteRecordingStream(conn.getMBeanServerConnection())) {
// 创建设置映射
var settings = new HashMap<String, String>();
// 跟踪 com.foo.Bar 类中执行时间超过 1 毫秒的方法
settings.put("jdk.MethodTrace#enabled", "true");
settings.put("jdk.MethodTrace#stackTrace", "true");
settings.put("jdk.MethodTrace#threshold", "1 ms");
settings.put("jdk.MethodTrace#filter", "com.foo.Bar");
// 订阅跟踪事件
r.onEvent("jdk.MethodTrace", event -> ...);
// 测量带有 jakarta.ws.rs.GET 注解的方法的执行时间和调用次数，并每 10 秒输出一次结果
settings.put("jdk.MethodTiming#enabled", "true");
settings.put("jdk.MethodTiming#filter", "@jakarta.ws.rs.GET");
settings.put("jdk.MethodTiming#period", "10 s");
// 订阅计时事件
r.onEvent("jdk.MethodTiming", event -> ...);
// 设置参数，然后进行 60 秒的计时和跟踪
r.setSettings(settings);
r.startAsync();
Thread.sleep(60_000);
r.stop();
}
}
当流启动时，远程 JVM 会通过注入字节码来插装指定的方法，以便在适当的时候发出 MethodTiming 和 MethodTrace 事件。60 秒后流停止时，注入的字节码会被移除。然后，在等待所有挂起的事件被处理完毕后，流会关闭，远程 JVM 会丢弃其记录数据，使系统恢复到原始状态。
你也可以以类似的方式使用 RemoteRecordingStream 类在一个进程内（例如在 Java 代理中）处理 MethodTiming 和 MethodTrace 事件。
如果同时运行多个记录，无论是远程启动还是本地启动，JFR 会应用所有过滤器的并集。
事件详情
jdk.MethodTiming 事件具有以下字段：
method- 被计时方法的名称，startTime- 发出事件的实际时间，invocations- 方法被调用的次数，minimum- 方法执行所花费的最小实际时间的近似值，average- 方法执行所花费的平均实际时间的近似值，maximum- 方法执行所花费的最大实际时间的近似值。
jdk.MethodTrace 事件具有以下字段：
method- 被跟踪方法的名称，startTime- 进入方法的实际时间，duration- 执行方法所花费的实际时间，eventThread- 执行方法的线程，以及stackTrace- 从被跟踪方法的调用者开始的堆栈跟踪。
average 和 duration 字段的精度取决于获取时间戳所需的时间，而这又取决于硬件和操作系统。
为一个方法记录的持续时间包括它调用的任何方法的执行时间。
未来工作
有时，要计时或跟踪的类实现了一个已知接口，但类本身的名称未知。在这种情况下，如果能够在过滤器中指定接口，使实现该接口的每个类都被计时或跟踪，会很方便。我们可以在未来添加这样的功能，而无需改变此设计。
替代方案
- JFR 在计时或跟踪时可以记录方法参数和非静态字段。然而，这可能会使其被用作泄露敏感信息的攻击途径，无论是通过未经审查的第三方库以编程方式，还是通过恶意构造的配置文件。
- 过滤器语法可以允许指定特定的方法名重载。然而，这会使语法复杂化，因为逗号分隔的参数名会与分隔 JFR 选项的逗号冲突。
- 过滤器语法可以接受通配符，但这可能会导致被插装的方法数量过多，使应用程序停止运行。
- 为了防止被插装的方法数量过多，JFR 可以限制可插装的方法数量。然而，在某些情况下，这可能是可以接受的。例如，静态初始化器只被调用一次，所以要求对所有静态初始化器进行计时或跟踪并非不合理。
风险与假设
指定一个包含注入的插装字节码所使用的 JDK 方法的过滤器可能会导致无限递归。JFR 试图避免这种情况，但其机制很脆弱。如果你发现了这种递归，请提交错误报告；同时，你可以通过从过滤器中删除 JDK 方法来避免递归。