Профилирование JVM: async-profiler, JFR и JMH

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

Честное измерение требует не одного инструмента, а дисциплины: понимать, что именно семплирует профайлер, доверять результату только после кросс-проверки независимым инструментом и не путать микробенчмарк с реальной нагрузкой. В этой статье — на живом стенде с заранее известным внутренним устройством нагрузки — JFR и async-profiler гоняются на одном и том же коде, и результаты сверяются друг с другом.

По аналогии с профилированием в Go и C++Скоро, но с учётом двух вещей, которых нет ни в Go, ни в C++: JIT-компиляции (код «разогревается» и меняет форму во время выполнения) и GC-пауз, которые сами по себе искажают тайминги, если их не учитывать отдельно.

В статье

• Стенд: нагрузка с известной начинкой
• Java Flight Recorder: профилирование без плясок с бубном
• async-profiler: независимая проверка
• Кросс-верификация и находка, которую не подогнали
• GC-паузы: Serial GC вместо ожидаемого G1
• JMH: почему наивный микробенчмарк врёт
• От микро к макро

Стенд: нагрузка с известной начинкой

Профилировать интереснее всего код, устройство которого заранее известно — тогда результат профайлера можно сверить с ожиданием и честно зафиксировать, где интуиция совпала с реальностью, а где нет. Стенд — однопоточный Workload, каждая итерация которого делает две независимые вещи:

while (System.nanoTime() < endNanos) {
    // --- горячий CPU-путь ---
    rnd.nextBytes(hashBuf);
    hashAccumulator ^= HashUtil.fnv1a(hashBuf);

    int[] toSort = randomInts(rnd, SORT_ARRAY_SIZE);
    int[] sorted = SortUtil.mergeSort(toSort);
    hashAccumulator ^= sorted[0] ^ sorted[sorted.length - 1];

    // --- аллокации ---
    List<Order> batch = new ArrayList<>(ORDERS_PER_ITERATION);
    for (int i = 0; i < ORDERS_PER_ITERATION; i++) {
        batch.add(OrderFactory.create(iterations * ORDERS_PER_ITERATION + i, rnd));
    }
    ordersCreated += batch.size();
    hashAccumulator ^= batch.size();

    iterations++;
}

Два источника нагрузки специально разведены и оба — «наш» код, а не заинлайненная тривиальщина или вызов JDK-примитива:

• CPU: ручной FNV-1a хэш по 8 КБ буферу (HashUtil.fnv1a) плюс рекурсивный merge sort на массиве из 2000 int, реализованный вручную (SortUtil.mergeSort/merge), а не через Arrays.sort.
• Аллокации: пачка из 500 Order — record с полями String id, double amount, Instant ts — на каждую итерацию, причём id собирается конкатенацией строк (типичный «случайный» источник аллокаций в прикладном коде, не StringBuilder явно). Пачка тут же становится мусором — умышленно, чтобы создать давление на young-GC.

static int[] mergeSort(int[] input) {
    if (input.length <= 1) {
        return input;
    }
    int mid = input.length / 2;
    int[] left = mergeSort(java.util.Arrays.copyOfRange(input, 0, mid));
    int[] right = mergeSort(java.util.Arrays.copyOfRange(input, mid, input.length));
    return merge(left, right);
}

private static int[] merge(int[] left, int[] right) {
    int[] result = new int[left.length + right.length];
    int i = 0;
    int j = 0;
    int k = 0;
    while (i < left.length && j < right.length) {
        result[k++] = (left[i] <= right[j]) ? left[i++] : right[j++];
    }
    while (i < left.length) {
        result[k++] = left[i++];
    }
    while (j < right.length) {
        result[k++] = right[j++];
    }
    return result;
}

Каждый уровень рекурсии аллоцирует новый int[] (Arrays.copyOfRange на входе, результирующий массив в merge), а глубина рекурсии для 2000 элементов — log2(2000) ≈ 11, то есть на одну сортировку — десятки временных массивов. Это важно держать в голове: тот же метод, который доминирует по CPU, окажется и в топе аллокаций.

Прогон — 40 секунд, eclipse-temurin:25-jdk в Docker, -Xms128m -Xmx512m. Числа в статье host-зависимы (конкретный прогон снят на Docker Desktop с WSL2-бэкендом) — важен не абсолютный процент, а то, что в топе оказываются реальные методы стенда, а не абстракция, и что два независимых инструмента сходятся на одном и том же ответе.

Java Flight Recorder: профилирование без плясок с бубном

JFR встроен в JDK начиная с Java 11 (раньше был проприетарной фичей Oracle JDK) — не нужно ничего скачивать и подключать нативных агентов. Оверхед достаточно низкий, чтобы держать JFR включённым в продакшене постоянно или включать по требованию через JMX — это профайлер, рассчитанный на то, чтобы работать не только на локальном стенде, а на живом сервисе под реальным трафиком.

Событий JFR умеет писать много: jdk.ExecutionSample (стек-семплы потоков — «кто выполняется прямо сейчас»), jdk.ObjectAllocationSample (аллокации, адаптивно семплируемые с целевой частотой — единый event начиная с JDK 16, пришедший на смену пер-TLAB событиям ObjectAllocationInNewTLAB/OutsideTLAB), jdk.GCPhasePause (паузы GC по фазам), jdk.JavaMonitorEnter/jdk.ThreadPark (блокировки и ожидания), jdk.SocketRead/jdk.FileWrite (I/O). Профиль settings=profile включает более частое семплирование ценой чуть большего оверхеда, чем профиль default — годится для целевого прогона на стенде.

docker run --rm -m 1g -v "$JAR_DIR:/app" "$IMAGE" \
  java -Xms128m -Xmx512m \
  -XX:StartFlightRecording=filename=/app/rec.jfr,settings=profile,dumponexit=true \
  -jar /app/profiling.jar "$DURATION"

docker run --rm -v "$JAR_DIR:/app" "$IMAGE" jfr summary /app/rec.jfr

-XX:StartFlightRecording не требует ни агента, ни перезапуска — флаг можно добавить к любому java-запуску. Готовую запись (.jfr) дальше разбирает либо CLI (jfr print --events ...), либо JDK Mission Control (GUI с готовыми view для hot-методов, аллокаций, GC, блокировок) — для локального разбора и построения flame graph по записи MC удобнее, для CI/скриптов достаточно jfr print.

На записи в 43 секунды (сама нагрузка — 40 с, JFR чуть длиннее за счёт старта и финализации) jdk.ExecutionSample дал 3394 семпла. По листовому фрейму стека — то есть по методу, который выполнялся в момент семпла, — топ выглядит так:

Workload$SortUtil.merge          1942 семпла   57.2%
Workload.main                     426 семплов  12.6%
Workload$SortUtil.mergeSort       388 семплов  11.4%
java.util.Random.nextBytes        249 семплов   7.3%
java.util.Arrays.copyOfRange      176 семплов   5.2%
java.time.Clock.currentInstant    106 семплов   3.1%

SortUtil.merge — больше половины всех CPU-семплов. Это ожидаемо в духе «мы же сами написали рекурсивный merge sort», но конкретную цифру (57.2%, а не «где-то много») даёт только измерение, а не код-ревью на глаз.

Топ аллокаций (jdk.ObjectAllocationSample, 11 777 семплов, агрегация по сумме weight — приблизительному объёму аллоцированной памяти на класс):

int[] — около 83% семплов аллокаций (9775 из 11 777) и абсолютное большинство суммарного веса. Это та же причина, что и с CPU: каждый уровень рекурсии merge sort аллоцирует свежий массив. Workload$Order и String в списке — прямое подтверждение, что аллокационная часть нагрузки действительно генерирует мусор нашего кода, а не только служебные объекты JDK.

async-profiler: независимая проверка

async-profiler — нативный агент (не входит в JDK, качается отдельно): perf_events на Linux запускает (триггерит) момент семпла через аппаратные/ОС-счётчики, а сам Java-стек в этот момент разворачивается через AsyncGetCallTrace — это два звена одного механизма, а не альтернатива. Ключевое отличие от JFR — не точность, а отсутствие safepoint bias: jdk.ExecutionSample умеет семплировать поток только в safepoint’ах (что смещает картину в пользу определённых мест в коде), а async-profiler берёт семпл в произвольной точке через ОС. Поэтому совпадение ответов двух настолько разных по механизму профайлеров — сильный сигнал, а не совпадение доверия к одному инструменту.

AP_HOME="/ap/async-profiler-${AP_VERSION}-${AP_ARCH}"

# CPU-профиль
docker run --rm -m 1g -v "$JAR_DIR:/app" -v "$AP_CACHE:/ap" "$IMAGE" \
  java -Xms128m -Xmx512m \
  -agentpath:${AP_HOME}/lib/libasyncProfiler.so=start,event=cpu,collapsed,file=/app/cpu.collapsed \
  -jar /app/profiling.jar "$DURATION"

# alloc-профиль
docker run --rm -m 1g -v "$JAR_DIR:/app" -v "$AP_CACHE:/ap" "$IMAGE" \
  java -Xms128m -Xmx512m \
  -agentpath:${AP_HOME}/lib/libasyncProfiler.so=start,event=alloc,collapsed,file=/app/alloc.collapsed \
  -jar /app/profiling.jar "$DURATION"

collapsed-формат — по одной строке на уникальный стек вызовов (фреймы через ;) плюс счётчик семплов, например:

Workload.main;Workload$SortUtil.mergeSort;...;Workload$SortUtil.merge 1
Workload.main;Workload$OrderFactory.create;java/time/Instant.now;java/time/Clock.currentInstant 1

Это тот самый формат, из которого строится flame graph: ширина блока на графике — доля семплов, где данный фрейм присутствует в стеке, глубина — позиция во вложенности вызовов. SortUtil.merge на графике по этой нагрузке выглядел бы самым широким блоком на верхнем уровне стека — том же самом, что и в топе JFR.

Кросс-верификация и находка, которую не подогнали

Ключевой вопрос при чтении любого профиля — «а можно ли этому верить, или это артефакт конкретного инструмента и семплирования». Ответ здесь — да, потому что async-profiler на том же коде и той же нагрузке (3993 CPU-семпла в этом прогоне против 3394 у JFR — разное число семплов ожидаемо: разные механизмы семплирования и частота) даёт тот же лидер:

2178  Workload$SortUtil.merge                        54.5%
 465  Workload.main
 194  AtomicLong.compareAndSet  (Random.next)
 180  Arrays.copyOfRange
 138  Random.nextBytes
  84  Workload$SortUtil.mergeSort
  17  Workload$HashUtil.fnv1a

SortUtil.merge — 57.2% у JFR и 54.5% у async-profiler. Разница в проценте укладывается в погрешность выборки (разное количество семплов, разная точка семплирования в тиковом цикле), но лидер один и тот же. Та же картина по аллокациям: async-profiler event=alloc отдаёт int[] на первом месте (104 245 единиц веса из ~126 563 в этом прогоне, около 82%) — та же пропорция, что и в JFR (~83%). Два независимых механизма семплирования — периодический стек-семплинг потоков в JFR и perf_events/AsyncGetCallTrace в async-profiler — согласны друг с другом. Это и есть практическая проверка, что профайлер «не врёт»: если бы числа резко расходились, стоило бы подозревать артефакт одного из инструментов, а не доверять первому попавшемуся результату.

Отдельного внимания заслуживает результат, который не подтвердил исходную гипотезу. При проектировании стенда ожидалось, что ручной FNV-1a хэш по 8 КБ буферу будет заметным hot-path — байтовый цикл с XOR и умножением на каждый байт выглядит недёшево. На практике хэш оказался на последнем месте: 17 семплов из 3394 у JFR (меньше 1%), последняя строчка и у async-profiler. Merge sort на 2000 элементах с ручным слиянием оказался ощутимо дороже, чем однопроходный хэш по 8 КБ — цифра не подогнана под красивый вывод, это то, что реально показал профайлер.

Это и есть главный практический урок: оценить стоимость операции «на глаз» нельзя — рекурсия с логарифмической глубиной и аллокациями на каждом уровне может оказаться дороже линейного прохода, который интуитивно кажется более «тяжёлым». Профилировать, а не гадать — не лозунг, а единственный способ узнать, где действительно горячо.

GC-паузы: Serial GC вместо ожидаемого G1

На записи в 43 секунды jdk.GCPhasePause дал следующую картину: JVM сама выбрала Serial GC (DefNew/SerialOld) — эргономический выбор для маленькой кучи (-Xmx512m; современные JVM переключаются на Serial при небольшом размере кучи и малом числе доступных CPU, а не используют G1 по умолчанию во всех случаях). Пауз — 1835 young GC, суммарно 141.5 мс (около 0.33% от wall time записи), диапазон от 0.034 мс до 9.34 мс. Максимум пришёлся на самую первую паузу цикла (прогрев/первичная разметка eden), дальше паузы стабильно держались в районе 0.04–0.2 мс — небольшой eden при однопоточной Serial-нагрузке очищается почти мгновенно.

Это стоит честно оговорить, а не выдавать за общее правило: числа в этой секции — про Serial GC на маленькой куче, не про G1. Если нужно продемонстрировать поведение G1 (паузы по SLA, -XX:MaxGCPauseMillis, смешанные коллекции), стенд для этого должен быть отдельным — с явным -XX:+UseG1GC и заметно большим -Xmx, где G1 реально успевает проявить свою модель регионов и инкрементальный сбор. Здесь JVM выбрала Serial сама, и подавать эти цифры как «типичные паузы G1» было бы некорректно — это ловушка, в которую легко попасть, если читать GC-цифры без учёта того, какой именно коллектор их произвёл.

Показательно другое: несмотря на десятки миллионов аллоцированных объектов за прогон, GC почти не виден на фоне нагрузки. Много аллокаций не означает автоматически, что GC — узкое место: короткоживущий мусор в небольшом eden при однопоточном Serial GC обрабатывается почти бесплатно. Именно поэтому важно смотреть на конкретные jdk.GCPhasePause, а не полагаться на общее ощущение «много объектов — плохо».

flowchart LR
  W["Workload\n(один и тот же код)"] --> J["JFR\nStartFlightRecording"]
  W --> A["async-profiler\nagentpath libasyncProfiler.so"]
  J --> JR["ExecutionSample: merge 57.2%\nObjectAllocationSample: int[] ~83%"]
  A --> AR["event=cpu: merge 54.5%\nevent=alloc: int[] ~82%"]
  JR --> V{"Один лидер\nв обоих?"}
  AR --> V
  V -->|"да"| OK["Профилю можно доверять"]

  style W fill:#f9f3e3,stroke:#8b7355
  style J fill:#c9e4c5,stroke:#5b8a5e
  style A fill:#c9e4c5,stroke:#5b8a5e
  style OK fill:#c9e4c5,stroke:#5b8a5e

JMH: почему наивный микробенчмарк врёт

Профайлер — инструмент для готового приложения под нагрузкой. Когда вопрос уже, «какой из двух вариантов реализации метода быстрее», нужен другой инструмент — микробенчмарк. Но написать честный микробенчмарк на JVM вручную — ловушка на ловушке: цикл вида «замерить System.nanoTime(), вызвать метод N раз, замерить снова» почти гарантированно врёт.

Первая причина — JIT. Первые итерации выполняются интерпретатором или C1-компилятором, JIT дооптимизирует (вплоть до C2) код только после того, как метод достаточно «горячий», — без warmup-фазы бенчмарк меряет смесь холодного и разогретого кода, а не установившееся поведение. Вторая причина — dead code elimination: если результат вызова метода нигде не используется, оптимизатор вправе выбросить сам вызов, и бенчмарк молча измеряет пустой цикл.

JMH (Java Microbenchmark Harness, тот же проект, что разрабатывает OpenJDK) решает обе проблемы системно, а не через самодельные обходы:

• отдельная warmup-фаза — итерации прогрева не попадают в измерение, замер начинается только после того, как JIT стабилизировал горячий код;
• Blackhole — API, которое «поглощает» результат вычисления так, чтобы JIT не мог доказать, что вызов не имеет побочных эффектов, и не имел права его выкинуть;
• режимы измерения — throughput (операций в единицу времени), average time, sample time (гистограмма по перцентилям отдельных вызовов), single-shot — под разные вопросы нужен разный режим, throughput и average time — не взаимозаменяемы для выводов о хвостовых задержках.

Отдельная категория ловушек — не про JMH-механику, а про то, что измеряется: аллокатор и кеш процессора ведут себя по-разному в изолированном микробенчмарке и в реальном сервисе с работающим GC и конкурирующими потоками, поэтому микробенчмарк «метод A быстрее метода B на 15%» не всегда переносится на прод один в один. И отдельно — coordinated omission: если генератор нагрузки ждёт ответа перед отправкой следующего запроса, а система в какой-то момент замедлилась, реальные хвостовые задержки systematically занижаются — время, потраченное на ожидание уже отправленного, но ещё не обработанного запроса, просто не попадает в замер. Для JMH это актуально в режиме sample time, если внешний генератор нагрузки собран наивно.

От микро к макро

Микробенчмарк и профиль реального сервиса отвечают на разные вопросы, и путать их — источник ложных выводов. JMH хорош, чтобы сравнить две реализации одного метода в изоляции. Он плохо подходит, чтобы предсказать поведение сервиса под нагрузкой: false sharing (конкуренция потоков за одну кеш-линию из-за соседних полей) и escape analysis (JIT решает, может ли объект быть аллоцирован на стеке, а не в куче, если не «убегает» за пределы метода) — оба эффекта чувствительны к тому, что происходит вокруг метода, а не только внутри него, и в изолированном микробенчмарке могут вести себя иначе, чем в составе большого сервиса.

Практический вывод стенда этой статьи — профиль реального (пусть и синтетического) сервиса под нагрузкой честнее интуиции и честнее изолированного микробенчмарка одновременно. Когда узкое место найдено профайлером и подтверждено независимым инструментом, дальше вопрос не «как микрооптимизировать этот метод», а архитектурный: снизить глубину рекурсии, изменить структуру данных, вынести аллокации из горячего пути. Микрооптимизация метода, который и так составляет 2% профиля, не даст результата, сравнимого с архитектурным решением проблемы, которая реально доминирует в 57% — а какая доминирует, можно узнать только измерением.

Документация и первоисточники

• async-profiler
• JDK Flight Recorder
• JMH
• Из серии: Конкурентность на JVM: virtual threads, корутины и reactive
• Из серии: JVM в production: конфигурация, graceful shutdown, observability и GC
• Смежное: JVM-сервис под нагрузкой: virtual threads, пулы и reactive для 1000 in-flight