JEP draft: JFR Method Timing & Tracing

Summary

Extend JDK Flight Recorder (JFR) to support bytecode-based method timing and tracing for quick and easy use.

Goals

• Gather method invocation statistics that are not sample-based.
• Allow method execution time and stack traces to be collected for specific methods without requiring source code modifications.
• Allow method selection via command-line arguments, jcmd commands, .jfc configuration files, and Java Management Extensions (JMX).
• Display results in the shell using the 'jfr view' command for recording files and on a live JVM using the 'jcmd JFR.view' command.

Non-Goals

• It is not a goal to collect method parameters and instance variables.
• It is not a goal to select methods that lack a bytecode representation, for example, non-static or non-default interface-methods.
• It is not a goal to trace a large number of classes simultaneously, as this would significantly degrade performance; method sampling is preferred for such use cases.
• It is not a goal to stay within JFR's current default goal of less than 1% CPU overhead when method timing and tracing is used.

Motivation

Tracing and timing method invocations help developers understand which methods are being called, how long they take to execute, and how they interact with each other. This information is useful for identifying performance bottlenecks, diagnosing the root causes of bugs, and optimizing code. For instance, if an application takes an unusually long time to start, tracing static initializers can reveal class loading that could be deferred to a later stage. Another example is when optimizing a method; timing its execution can confirm whether the code change has actually improved performance. An application may fail due to resource exhaustion, such as running out of database connections. By tracing the method responsible for opening a connection, developers can identify all points where the database is being accessed and take steps to manage resources more efficiently.

During development, developers use various tools to analyze method execution, including:

• Java Microbenchmark Harness (JMH) to measure method execution times.
• Java Debug Interface (JDI) capable debuggers to set breakpoints and inspect the call stack.

Tracing and timing in production and testing environments outside of the developer machine pose challenges. Current approaches include:

• Adding temporary log statements or JFR events to methods under investigation, a practice that is cumbersome at best and not feasible for third-party libraries or classes in the JDK.
• Using sample-based profilers, such as the one built into JFR or third-party tools like Async-profiler, which capture stack traces for frequently executed methods but fall short of tracing and timing every invocation.
• Using a Java agent, such as the JDK Mission Control (JMC) Agent, that collects method traces by injecting probes. This approach works, but performing instrumentation directly in the JDK offers performance advantages. For example, the JVM can perform method filtering, eliminating the need to parse the bytecode of every loaded class twice, and simplifying usage since developers can specify methods to be traced without configuring an agent.

The JDK should provide means to time and trace method invocations with low overhead, allowing developers to easily and efficiently analyze and optimize their applications.

Description

The feature will be implemented as two new events, jdk.MethodTrace and jdk.MethodTiming, which both accept a filter to select the methods to trace and time. For example, to see what triggered a HashMap resize, the filter setting of the MethodTrace event could be set like this:

$ 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
      ...
      javax.swing.SwingUtilities.invokeLater(Runnable) line: 1415
      java2d.J2Ddemo.main(String[]) line: 674
    ]
}

To simplify configuration, default.jfc and profile.jfc files will be enhanced with two .jfc options: method-trace and method-timing. These options will control the filter setting of the MethodTrace and MethodTiming events. The method-trace option records a stack trace for methods that match the filter. The method-timing option counts the number of invocations and the average execution time for methods that match the filter. To display the results, the 'jfr view' and 'jcmd JFR.view' commands will be extended with views for both method tracing and timing.

For example, if an application suffers from slow startup, timing the execution of all static initializers may give an idea of where lazy initialization could be beneficial. By omitting the class name and using <clinit> as the method name in the filter, all static initializers are traced.

$ java '-XX:StartFlightRecording:method-timing=::<clinit>,report-on-exit=method-timing' ...

                              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
...

If the constructor of a class needs to be traced or timed, <init> is used as the method name. Besides a method, the filter can be a class, in which case all the methods in that class are timed or traced. The filter can also be an annotation, in which case the annotated method is traced or timed. For example, to see the number of times a REST endpoint is invoked and measure the approximate execution time:

$ jcmd <pid> JFR.start method-timing=@jakarta.ws.rs.GET

Multiple filters can be specified by separating them with a semicolon. In the following example, the creation and destruction of file descriptors are traced. By looking at where the events do not match up, it is possible to find where file descriptors are leaking.

$ java '-XX:StartFlightRecording:filename=fd.jfr,method-trace=java.io.FileDescriptor::<init>;java.io.FileDescriptor::close' ...
$ jfr view --cell-height 10 MethodTrace fd.jfr

                                                  Method Trace

Start Time    Duration Event Thread     Stack Trace                                     Method                         
---------- ----------- ---------------- ----------------------------------------------- -------------------------------                             
10:50:11   0.000167 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>()                                    
                                        sun.security.provider.SunEntries.<clinit>()                                    
                                        sun.security.provider.Sun.<init>()                                             
                                        sun.security.jca.ProviderConfig.getProvider()                                  
                                        sun.security.jca.ProviderList.getProvider(int)                                 
                                        sun.security.jca.ProviderList$2.get(int)                                                                                                                                
10:50:20    0.00113 ms AWT-EventQueue-0 java.io.FileInputStream.<init>(File)            java.io.FileDescriptor.<init>()
                                        java.io.FileInputStream.<init>(String)                                         
                                        java.io.FileReader.<init>(String)                                              
                                        java2d.demos.Mix.BezierScroller.getFile()                                      
                                        java2d.demos.Mix.BezierScroller.step(int, int)                                 
                                        java2d.Surface.paint(Graphics)                                                 
                                        javax.swing.JComponent.paintChildren(Graphics)                                 
                                        javax.swing.JComponent.paint(Graphics)                                         
                                        javax.swing.JComponent.paintChildren(Graphics)                                 
                                        javax.swing.JComponent.paint(Graphics)                         
...

The grammar for the new filter setting is:

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 ::= see JLS 3.8

Users who do not want to add JFR events to their code, perhaps because they think it is noisy or because they want to avoid a dependency on the jdk.jfr module, can create custom annotations, for example:

@Retention(RUNTIME)
@Target({ TYPE, METHOD })
public @interface StopWatch {
}

@Retention(RUNTIME)
@Target({ TYPE, METHOD })
public @interface Initialization {
}

@Retention(RUNTIME)
@Target({ TYPE, METHOD })
public @interface Debug {
}

These annotations can be added to classes or methods that are worth investigating. When there is a need to troubleshoot the application, the annotation can be specified, and all the annotated methods will be timed or traced, for example:

$ java -XX:StartFlightRecording:method-trace=@example.Debug
$ java -XX:StartFlightRecording:method-timing=@example.Initialization,@example.StopWatch

The resulting MethodTrace events can be correlated with other events that JFR emits, such as events for lock contention, method sampling, or I/O, to understand why the annotated parts of the program were slow.

For configuration over the network, JMX and the RemoteRecordingStream class in the jdk.management.jfr module can be used. In the following example, a non-secure connection is made to a remote host where timing and tracing are enabled for 60 seconds.

JMXServiceURL url = new JMXServiceURL(“service:jmx:rmi:///jndi/rmi://example.com:7091/jmxrmi”);
 JMXConnector connector = JMXConnectorFactory.connect(url);
 try (var r = new RemoteRecordingStream(connector.getMBeanServerConnection())) {
     Map<String, String> settings = new HashMap<>();
     // Trace methods in class com.foo.Bar that takes more than 1 ms to execute
     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 -> ...);
     // Measure execution time and invocation count for methods with 
     // the jakarta.ws.rs.GET annotation and emit the result every 10 s.
     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 -> ...);    
     r.setSettings(settings);
     r.startAsync();
     Thread.sleep(60_000);
     r.stop();
}
connector.close();

Once the 60 seconds have passed, the RemoteRecordingStream is stopped, and the added bytecode for the MethodTrace and MethodTiming events are removed. The RemoteRecordingStream then waits for events that happened during the interval to be consumed. Finally, the stream is closed, and the recording data on the remote host is removed, leaving the system as it was before the RemoteRecordingStream was started. For in-process use, such as a Java Agent, the RecordingStream class can be used to consume MethodTrace and MethodTiming events in a similar manner.

In case multiple recordings are running at the same time, either started remotely or locally, the union of all the filters will be applied.

In scenarios where more than a few methods should be traced, a separate .jfc file can be created:

<?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>

It can then be used in conjunction with the default settings:

$ java -XX:StartFlightRecording:settings=timing.jfc,settings=default ...

Alternatives

• We considered recording method parameters and instance variables but rejected this approach because it turns JFR into an attack vector for extracting sensitive information, either programmatically in an unvetted third-party library or through a maliciously crafted .jfc file.

• Sometimes, developers cannot determine the specific class to instrument, such as an implementation of java.sql.Connection or java.lang.System.Logger. In these cases, specifying the interface provides a convenient way to instrument all implementing classes. This functionality could become part of a future enhancement without altering the existing design.

• We designed the filter grammar not to accept wildcards to prevent an excessive number of instrumented methods, which could bring the application to a halt. To maintain a simple filter syntax, we chose not to support method overloads that require comma-separated parameters, as they conflict with those used for option separation.

• The feature is not intended to be used on a large number of methods due to the enormous overhead it would impose. To prevent misuse, we considered setting a hard limit on the number of methods that can be instrumented but decided against it, as there are scenarios where it may be acceptable, such as timing every class initializer, which only occurs once in an application's lifecycle.