JEP 520: JFR Method Timing & Tracing

JEP 520: JFR Method Timing & Tracingopenjdk.org

RUN :

scripts/jep520/trace-method.sh

It is tracing specific method :

java \
  -XX:StartFlightRecording=filename="$TRACE_FILE",
  settings=profile,
  method-trace=com.wlodar.jeeps.jep520MethodTrace.BufferService::resizeBuffer \  <----HERE
  -cp target/classes \
  "$MAIN_CLASS"

results :

Recording created: jep520-method-trace.jfr

jdk.MethodTrace {
  startTime = 12:29:21.269 (2026-03-21)
  duration = 21.9 ms
  method = com.wlodar.jeeps.jep520MethodTrace.BufferService.resizeBuffer(int)
  eventThread = "main" (javaThreadId = 3)
  stackTrace = [
    com.wlodar.jeeps.jep520MethodTrace.BufferService.ensureCapacity(int) line: 36
    com.wlodar.jeeps.jep520MethodTrace.BufferService.warmupCache() line: 11
    com.wlodar.jeeps.jep520MethodTrace.MethodTraceDemo.main() line: 13
  ]
}

jdk.MethodTrace {
  startTime = 12:29:21.468 (2026-03-21)
  duration = 20.1 ms
  method = com.wlodar.jeeps.jep520MethodTrace.BufferService.resizeBuffer(int)
  eventThread = "main" (javaThreadId = 3)
  stackTrace = [
    com.wlodar.jeeps.jep520MethodTrace.BufferService.ensureCapacity(int) line: 36
    com.wlodar.jeeps.jep520MethodTrace.BufferService.parseInput(int) line: 26
    com.wlodar.jeeps.jep520MethodTrace.BufferService.importData(int) line: 16
    com.wlodar.jeeps.jep520MethodTrace.MethodTraceDemo.main() line: 19
  ]
}

During development, we already have good tools for analyzing method execution: The Java Microbenchmark Harness (JMH) can measure method execution times, and debuggers built on top of the Java Debug Interface (JDI) can set breakpoints and inspect call stacks.

During testing and production, however, timing and tracing pose challenges. There are several approaches, none fully satisfactory:

• logs

• java agents

• not accurate sample based profilers

More about disadvantages on jep page Also from jep page :

We introduce two new JFR events, jdk.MethodTiming and jdk.MethodTrace. They both accept a filter to select the methods to time and trace.

For example, to see what triggers the resize of a HashMap, you can configure the MethodTrace event's filter when making a recording and then use the jfr tool to display the recorded event:

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