Семплирующие профили не показывают реальное число вызовов и их длительность — а значит, мимо может пролетать важная боль. В новом переводе от команды Spring АйО на примерах показано, как включить инструментальную трассировку в async-profiler и что даёт новая фича latency: от ловли неожиданного System.gc() и источников OutOfMemoryError до точного замера «долгих» вызовов с порогом и разбором в JMC через JFR-события. 

Разбираем накладные расходы, хитрости вроде interval, практичные кейсы (почему ArrayList.contains и AbstractSet.removeAll могут внезапно стать O(N*M) и как это починить), а ещё сравниваем подход async-profiler с нововведениями в рамках JDK 25 (JEP 520), где последний имеет ряд недостатков.

Если вам нужны точные пути выполнения и реальная latency без убийства продакшена — это must-read.

Предыстория

Async-profiler часто описывают как легковесный семплирующий профилировщик для Java. Семплирование означает, что профилировщик собирает статистическую информацию о выполнении программы, периодически прерывая её для получения stacktrace. Такой подход оказывает минимальное влияние на производительность отслеживаемого приложения, но основным его недостатком является невозможность точно определить количество вызовов методов или продолжительность каждого из них.

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

Базовая инструментализация

Возможности инструментализации появились в async-profiler начиная с версии 1.7, выпущенной в 2020 году. С помощью опции -e можно указать Java-метод для инструментирования — при этом будут зафиксированы все его вызовы. Это может быть как внутренний метод JDK, так и любой метод приложения, вне зависимости от его модификатора доступа — public или private.

Предположим, мы пытаемся выяснить причину загадочного Full GC в логах:

[2515.127s][info][gc] GC(50) Pause Full (System.gc()) 817M->29M(156M) 28.328ms

Возможно, что кто-то вызывает System.gc(), и async-profiler может точно показать, откуда происходит этот вызов:

asprof -e java.lang.System.gc -f gc.html AppName

Эта команда собирает стектрейсы всех вызовов System.gc() и визуализирует их в виде flame graph.

Удивительно, но System.gc() действительно вызывается прямо в ядре OpenJDK при определённых условиях нехватки памяти. Кстати, чтобы отследить источник таких ошибок out-of-memory, можно воспользоваться той же возможностью async-profiler: просто запрофилируйте конструктор OutOfMemoryError:

asprof -e "java.lang.OutOfMemoryError.<init>" --cstack vmx -f oom.html AppName

Обратите внимание на опцию --cstack vmx: она включает наиболее детальный режим обхода стека, отображая все Java и нативные фреймы стек фреймы вперемешку. В этом примере OutOfMemoryError выбрасывается из метода JDK map0.

Можно использовать символ , чтобы профилировать несколько методов одновременно.
Например, -e java.io.FileInputStream.read охватит методы read, readNBytes и readAllBytes.
Более широко — -e java.io.FileInputStream.* проинструирует все методы класса FileInputStream.

О других типах инструментализации, поддерживаемых async-profiler, вы можете узнать из моего доклада на конференции Devoxx UK.

Отслеживание задержек

Хотя функция профилирования Java-методов существует уже давно, ранее она позволяла отслеживать только сами вызовы методов, но не продолжительность их исполнения. Опция latency, добавленная в #1421, устраняет этот зазор. Она уже доступна в Nightly-сборках.

Как и раньше, аргумент -e (или event при запуске профилировщика как Java агента) указывает метод для инструментирования. Теперь, с опцией latency, async-profiler будет записывать продолжительность каждого вызова. В сочетании с опцией total flame graph будет накапливать суммарную продолжительность, а не количество вызовов.

Вот пример, как измерить общее время, затраченное внутри ByteBuffer.allocateDirect:

java -agentpath:libasyncProfiler.so=start,event=java.nio.ByteBuffer.allocateDirect,latency,total,file=duration.html MyApp

Чтобы получить максимум от этой функции, используйте профилирование latency с форматом вывода JFR. В этом случае async-profiler фиксирует каждый отдельный вызов указанного метода с отметкой времени, продолжительностью и трассировкой стека. Далее вы можете проанализировать запись в JDK Mission Control (JMC) на вкладке Event Browser — ищите события типа Method Trace.

А что, если интересующий нас метод вызывается миллионы раз? Чтобы упростить анализ и, что не менее важно, снизить накладные расходы на трассировку байткода, можно отфильтровать только те вызовы, которые выполняются дольше заданного времени — просто передайте пороговую длительность в аргументе latency.

Например, мы хотим найти использования ArrayList.contains, который, как правило, не рекомендуется из-за своей линейной сложности. Однако проблем с этим методом нет, если список содержит всего несколько элементов. Наша цель — выявить вызовы ArrayList.contains, занимающие более 50 микросекунд:

asprof -e java.util.ArrayList.contains --latency 50us -f latency.jfr PID

Открыв профиль в JMC, мы увидим лишь небольшое количество событий типа Method Trace и сможем быстро проанализировать самые долгие из них.

На этом скриншоте видно, что самый медленный вызов ArrayList.contains происходит из метода AbstractSet.removeAll. На самом деле, это не уникальная проблема. В зависимости от относительных размеров коллекций, реализация removeAll может перебирать либо исходный Set, либо переданную коллекцию. Если вам не повезло, и переданная коллекция оказалась больше множества, сложность алгоритма может вырасти до O(N*M). Если вы сталкивались с подобной ситуацией, решением будет заменить set.removeAll(list) на list.forEach(set::remove).

Влияние на производительность

Теперь, когда вы ознакомились с возможностями инструментирующего профилировщика методов, возникает закономерный вопрос: насколько вообще это все бьет по перформансу? Безопасно ли включать такую трассировку в продакшене?

Короткий ответ: трассировка методов была разработана с расчётом на высокую производительность. Само собой, все это лишь инструментация байткода: для каждого отслеживаемого метода async-profiler вставляет вызов получения временной метки в начале метода и ещё один вызов на каждой точке выхода. Такая инструментализация не мешает JIT-компиляции метода и обычно добавляет всего несколько наносекунд.

Если продолжительность выполнения метода превышает заданный порог latency, происходит вызов JNI для сбора стектрейса и записи события. Это самая затратная часть трассировки. Отсюда правило: выбирайте параметр latency разумно, чтобы избежать избыточной трассировки коротких вызовов.

Для среднего приложения запись порядка 100 вызовов в секунду не оказывает заметного влияния на производительность.

Другой способ снижения накладных расходов — задать ненулевой параметр interval. Например, interval=20 означает, что async-profiler будет записывать только один из каждых двадцати вызовов метода. Это может быть полезно для сбора гистограммы задержек без пеналти на каждый вызов.

Трассировка методов в JDK

Async-profiler поддерживает трассировку методов путем инструментации байткода во всех версиях JDK, начиная с 8-й.

Тем временем в JDK 25 появилась новая встроенная функция, которая на первый взгляд выглядит очень похожей.
JEP 520: JFR Method Timing & Tracing добавляет два события JFR: jdk.MethodTrace и jdk.MethodTiming. На самом деле, async-profiler использует то же самое событие для трассировки методов, стремясь к совместимости с внешними инструментами, как только они начнут поддерживать эту возможность. Однако существуют важные отличия.

В JEP 520 стектрейс события jdk.MethodTrace начинается с метода коллера. На мой взгляд, это неудачное архитектурное решение — исключать сам отслеживаемый метод, и вот почему.

1. Помимо самого ID метода, StackFrame содержит множество дополнительных данных, таких как тип фрейма. В разные моменты времени отслеживаемый метод может быть интерпретируемым, скомпилированным или заинлайненым. Информация о его статусе компиляции полезна для анализа причин аномальной задержки, которая, например, может быть связана с деоптимизацией.

2. Если у целевого метода несколько точек выхода, важно знать, какая именно была задействована. Это позволяет, например, сравнивать задержку в случае условного "cache hit" и при "cache miss". Вновь, одного метода здесь недостаточно — в отличие от StackFrame, который включает поля lineNumber и bytecodeIndex.

3. Когда отслеживаемый метод включён в стектрейс трассировки, визуализация в виде Flame Graph работает «из коробки». Без этого разработчикам различных тулов пришлось бы вручную обрабатывать событие jdk.MethodTrace и добавлять в стек синтетический фрейм с отслеживаемым методом.

По этим причинам мы решили включать в async-profiler инструментировать непосредственно не caller метод, а встраивать инструментацию в непосредственно callee, чтобы вся дополнительная информация сразу отображалась в JMC.

Как и многие другие события JFR, jdk.MethodTrace имеет ряд настроек, которые можно изменить через командную строку или в конфигурационном файле .jfc. В JEP 520 упоминается параметр threshold, предназначенный для трассировки только тех методов, выполнение которых занимает больше заданного времени. Однако на практике изменение threshold не даёт никакого эффекта, что указывает на то, что данная настройка пока не реализована. Это означает, что трассировка методов JFR на данный момент непригодна для событий с высоким объёмом.

Есть ещё одна интересная особенность трассировки методов в JDK: любые инструкции throw рассматриваются как точки выхода, даже если исключение перехватывается внутри того же самого метода. В результате все вызовы таких методов будут учитываться дважды.

void doubleCounted() {
    System.out.println("enter");
    try {
        throw new RuntimeException();
    } catch (RuntimeException e) {
        // handle exception in the same method
    }
    System.out.println("exit");
}

Я оставил багрепорты об обеих этих проблемах в OpenJDK: JDK-8367948, JDK-8367949.

Тем не менее, меня радует, что развитие OpenJDK движется в том же направлении. Это лишь подчёркивает актуальность инструментов профилирования в Java, включающих как семплирующие, так и инструментирующие профилировщики.

Заключение

Трассировка методов в async-profiler дополняет традиционное семплирование, предоставляя точные данные о количестве вызовов, путях выполнения и latency — всё это с тщательно продуманными мерами по минимизации накладных расходов.
С определёнными оговорками, JDK Flight Recorder также предлагает функцию трассировки и измерения времени выполнения методов начиная с JDK 25.

Присоединяйтесь к русскоязычному сообществу разработчиков на Spring Boot в телеграм — Spring АйО, чтобы быть в курсе последних новостей из мира разработки на Spring Boot и всего, что с ним связано.