JEP 520: JFR Method Timing & Tracing

Аннотация

Расширить JDK Flight Recorder (JFR) средствами для измерения времени выполнения и трассировки методов с помощью инструментирования байт-кода.

Цели

• Для вызовов методов записывать полную и точную статистику, а не неполную и неточную статистику на основе выборок.

• Дать возможность записывать время выполнения и трассировки стека для конкретных методов, не требуя изменений исходного кода.

• Дать возможность выбирать методы с помощью аргументов командной строки, файлов конфигурации, инструмента jcmd, а также по сети через Java Management Extensions API (JMX).

Что не является целью

• Целью не является запись аргументов методов или значений нестатических полей.

• Целью не является измерение времени выполнения или трассировка методов, у которых нет представления в байт-коде, например абстрактных, native-методов или нестатических методов интерфейсов, не являющихся методами по умолчанию.

• Целью не является одновременное измерение времени выполнения или трассировка большого числа методов, поскольку это значительно снизило бы производительность. В таких случаях используйте выборку методов.

• Как правило, JFR стремится создавать нагрузку на CPU меньше одного процента. Соблюдение этого ограничения при измерении времени выполнения и трассировке методов целью не является.

Мотивация

Измерение времени выполнения и трассировка вызовов методов помогают выявлять узкие места производительности, оптимизировать код и находить первопричины ошибок. Например, если приложение запускается необычно долго, трассировка статических инициализаторов может выявить загрузку классов, которую можно отложить на более поздний этап. Если метод был изменён, чтобы исправить ошибку производительности, измерение времени его выполнения может подтвердить, что исправление удалось. Если приложение завершается сбоем из-за того, что у него заканчиваются соединения с базой данных, трассировка метода, открывающего соединения, может подсказать, как эффективнее управлять этими соединениями.

На этапе разработки у нас уже есть хорошие инструменты для анализа выполнения методов: Java Microbenchmark Harness (JMH) может измерять время выполнения методов, а отладчики, построенные на основе Java Debug Interface (JDI), могут устанавливать точки останова и просматривать стеки вызовов.

Однако при тестировании и в продакшене измерение времени выполнения и трассировка создают трудности. Существует несколько подходов, и ни один из них не является полностью удовлетворительным:

• Добавлять временные операторы логирования или события JFR в исследуемые методы. В лучшем случае это громоздко, а для сторонних библиотек или классов JDK неосуществимо.

• Использовать профилировщики на основе выборок, например встроенный в JFR, или сторонние инструменты, например async-profiler. Эти инструменты собирают трассировки стека для часто выполняемых методов, но не позволяют измерять время выполнения и трассировать каждый вызов.

• Использовать Java-агент, например тот, что применяется в инструменте JDK Mission Control, чтобы инструментировать методы для генерации событий 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 или через jcmd для уже работающей JVM.

Мы дополняем 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 ::= see 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;

@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, например с событиями конкуренции за блокировки, выборки методов или ввода-вывода, чтобы определить, почему аннотированные части программы работали медленно.

Удалённая настройка

С помощью JMX и класса JFR RemoteRecordingStream можно настраивать измерение времени выполнения и трассировку по сети. Например:

import javax.management.remote.*;
import jdk.management.jfr.*;

/// Establish non-secure connection to remote host
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())) {

        // Create map for settings
        var settings = new HashMap<String,String>();

        // Trace methods in class com.foo.Bar that take 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");

        // Subscribe to trace events
        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");

        // Subscribe to timing events
        r.onEvent("jdk.MethodTiming", event -> ...);

        // Set the settings, then time and trace for 60 seconds
        r.setSettings(settings);
        r.startAsync();
        Thread.sleep(60_000);
        r.stop();

    }
}

При запуске потока событий удалённая JVM инструментирует указанные методы, внедряя байт-код для генерации событий MethodTiming и MethodTrace в зависимости от ситуации. При остановке потока событий, через 60 секунд, внедрённый байт-код удаляется. Затем, после ожидания обработки всех ожидающих событий, поток событий закрывается, а удалённая JVM удаляет данные записи, возвращая систему в исходное состояние.

Класс RemoteRecordingStream можно аналогичным образом использовать и для обработки событий MethodTiming и MethodTrace внутри процесса, например в Java-агенте.

Если одновременно выполняется несколько записей, запущенных удалённо или локально, JFR применяет объединение всех фильтров.

Подробности о событиях

Событие jdk.MethodTiming содержит следующие поля:

• method — имя метода, время выполнения которого измерялось,
• startTime — реальное время, когда было сгенерировано событие,
• invocations — число вызовов метода,
• minimum — приближённое значение минимального реального времени выполнения метода
• average — приближённое значение среднего реального времени выполнения метода
• maximum — приближённое значение максимального реального времени выполнения метода

Событие jdk.MethodTrace содержит следующие поля:

• method — имя трассированного метода,
• startTime — реальное время входа в метод,
• duration — реальное время, затраченное на выполнение метода,
• eventThread — поток, в котором выполнялся метод, и
• stackTrace — трассировка стека, начиная с метода, вызвавшего трассированный метод.

Точность полей average и duration зависит от времени, необходимого для получения метки времени, которое, в свою очередь, зависит от оборудования и операционной системы.

Длительность, записанная для метода, включает время выполнения всех вызываемых им методов.

Дальнейшая работа

Иногда класс, время выполнения которого нужно измерить или который нужно трассировать, реализует известный интерфейс, но имя самого класса неизвестно. В таких случаях было бы удобно указывать в фильтре интерфейс, чтобы измерялось время выполнения или трассировался каждый класс, реализующий этот интерфейс. Такую функциональность можно добавить в будущем, не меняя этот дизайн.

Альтернативы

• JFR мог бы записывать аргументы методов и нестатические поля при измерении времени выполнения или трассировке. Однако тогда его можно было бы использовать как вектор атаки для извлечения конфиденциальной информации — либо программно, непроверенной сторонней библиотекой, либо через злонамеренно составленный файл конфигурации.

• Грамматика фильтров могла бы позволять указывать конкретные перегрузки метода. Однако это усложнило бы синтаксис, поскольку имена параметров, разделённые запятыми, конфликтовали бы с запятыми, разделяющими параметры JFR.

• Грамматика фильтров могла бы допускать подстановочные символы, но это могло бы привести к чрезмерному числу инструментированных методов и остановить работу приложения.

• Чтобы предотвратить чрезмерное число инструментированных методов, JFR мог бы ограничить число методов, которые можно инструментировать. Однако существуют сценарии, в которых это может быть приемлемо. Например, статические инициализаторы вызываются только один раз, поэтому запрос на измерение времени выполнения или трассировку их всех вполне разумен.

Риски и допущения

Указание фильтра, включающего методы JDK, которые используются внедрённым инструментирующим байт-кодом, может привести к бесконечной рекурсии. JFR пытается этого избежать, но его механизм для этого ненадёжен. Если вы наблюдаете такую рекурсию, отправьте, пожалуйста, отчёт об ошибке; тем временем рекурсии можно избежать, исключив методы JDK из фильтра.