Профилирование Java через JFR и async-profiler находит тормозы продакшена там, где лабораторный стенд остаётся слепым

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

Лабораторный стенд не видит тормозов живого продакшена по системным причинам

Список причин длинный, и почти все они сводятся к отличиям сред. Стенд гоняет один сценарий с одним набором входов; продакшен смешивает на одном экземпляре виртуальной машины запросы разных типов, и профиль горячего вызова размывается чужими записями в кешах процессора. Виртуальная машина на стенде не успевает прогреться: первые тысячи вызовов исполняет интерпретатор и упрощённый компилятор C1, и замер на холодной машине описывает не приложение, а сам процесс его разогрева. Размер кучи на стенде обычно щедрее или скупее рабочего, сборщик мусора ведёт себя иначе, а конкуренция за мониторы возникает только при настоящем параллелизме, а не при трёх потоках нагрузочного теста.

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

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

Java Flight Recorder внутри HotSpot и события с низкой ценой записи

Java Flight Recorder встроен в HotSpot начиная с одиннадцатого выпуска JDK, который вышел в сентябре 2018 года и оформил механизм в открытый процесс улучшений под номером 328. До этого рекордер существовал в проприетарных сборках седьмого и восьмого поколений как платная функция, и его открытие перевело механизм в разряд стандартного инструмента любого JDK на базе HotSpot, включая сборки независимых поставщиков. Идея простая: виртуальная машина постоянно пишет в кольцевой буфер мелкие события, сборку мусора, блокировки мониторов, остановки в безопасных точках, выборки стеков, и приложение почти не замечает записи. Рекордер запускается на живом процессе и выгружается по требованию, без перезапуска:

jcmd 4321 JFR.start name=hot settings=profile duration=120s filename=hot.jfr
jcmd 4321 JFR.dump name=hot filename=after.jfr
jcmd 4321 JFR.stop name=hot

Событийный язык здесь главный. Выборка стека выполняющегося потока срабатывает по умолчанию каждые двадцать миллисекунд, пресет profile уплотняет шаг примерно вдвое. Отдельные события, вход в монитор, приостановку потока, выгрузку класса, собирают со своими порогами. С шестнадцатого выпуска JDK в наборе появилось выборочное событие аллокаций jdk.ObjectAllocationSample, и давление на кучу стало видно без инструментации кода. Настройки записи лежат в редактируемых файлах конфигурации, так что набор событий можно сузить под свою задачу. Для непрерывного наблюдения запись стартует вместе с приложением:

java -XX:StartFlightRecording=settings=profile,maxsize=200m,maxage=2h -jar app.jar

Кольцевой буфер ограничен объёмом и возрастом, старые события уходят, а окно проблемного интервала всегда можно выгрузить. Разбор файла делается утилитой jfr из состава JDK:

jfr summary hot.jfr
jfr print --events jdk.ExecutionSample hot.jfr

Первая команда печатает сводку по количествам событий, вторая выводит стеки выбранного типа. Графический разбор с деревьями вызовов и браузером событий выполняет JDK Mission Control, отдельное приложение с многолетней историей развития.

async-profiler собирает стеки без искажения безопасных точек

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

asprof -d 30 -f flame.html 4321

Через тридцать секунд в файле готовый интерактивный flame graph. Актуальная сборка 4.5 вышла в июле 2026 года, двоичные файлы поставляются для Linux x64 и arm64, а также для macOS. Набор режимов шире встроенного рекордера: процессорное время, аллокации, тактовое время ожидания, захват мониторов, нативные утечки. Режимы включаются отдельными ключами:

asprof -e alloc --alloc 500k -f alloc.html 4321
asprof -e lock --lock 10ms -f locks.html 4321
asprof -e wall -i 100ms -f wall.html 4321

Аллокационный режим опирается на быстрые уведомления от TLAB, не трогает байткод и не мешает компилятору выбрасывать лишние распределения: измеряются только реальные аллокации, а интервал задаётся значением вроде 500k, то есть одна выборка на каждые пятьсот килобайт. Для захвата мониторов устанавливается порог, по умолчанию десять миллисекунд, и профиль показывает, кто держит лок и кто его ждёт. Режим тактового времени охватывает все потоки независимо от состояния, поэтому его выбирают для диагностики хвостов и простоев ввода-вывода. Стеки включают нативные и ядерные кадры, а также потоки сборщика мусора и компилятора, которых обычные профилировщики не видят. Процессорный режим умеет работать как на встроенном таймере, так и через счётчики ядра, а вывод пишется прямо в формат JFR, и один файл читается любым разборщиком.

Для нативных утечек у профилировщика отдельный конвейер: режим nativemem записывает malloc, realloc, calloc и free с адресами, а утилита конвертера сопоставляет выделения с освобождениями и строит flame graph только по неосвобождённым блокам:

asprof start -e nativemem -f native.jfr 4321
asprof stop 4321
jfrconv --nativemem --leak native.jfr leaks.html

Отдельная экономия прилагается. Классическая связка из системного профилировщика и транслирующего агента требует сохранения указателя кадра в стеке, а флаг -XX:+PreserveFramePointer сам по себе отнимает до десяти процентов производительности. async-profiler обходится без него, и именно поэтому его пускают в продакшен охотнее.

Локализация задержки на живом сервисе от метрики до виновного метода

Типовой сеанс диагностики занимает полчаса и укладывается в шесть шагов:

1. подтвердить симптом по метрикам и выбрать окно, скажем пятнадцать минут, когда девяносто девятый перцентиль устойчиво выше нормы;
2. выгрузить из кольцевого буфера непрерывной записи JFR окно проблемного интервала, если такая запись включена заранее;
3. снять тридцатисекундный профиль процессорного времени через asprof и оценить, есть ли связь загрузки процессора с задержкой вообще;
4. при пустом процессорном профиле повторить замер в режиме тактового времени, который видит спящие и заблокированные потоки;
5. снять профиль захватов мониторов и профиль аллокаций, если подозрение падает на конкуренцию за локи или на давление на кучу;
6. оформить найденный метод в изолированный тест и закрепить регрессию в конвейере, чтобы находка не растворилась со следующим рефакторингом.

Логика пары соседних шагов стоит пояснения. Профиль процессорного времени отвечает на вопрос, кто считает. Профиль тактового времени отвечает, кто ждёт. Если задержка есть, а процессор спит, виноват почти всегда ввод-вывод, блокировка или сеть, и повторные снимки в том же режиме покажут ту же картину ожидания. Дерево вызовов в flame graph читается снизу вверх: ширина полосы это доля времени, широкая полоса у корня означает дорогую рамку, растянутая через всю высоту устойчивую горячую точку. Десять минут чтения такого графа обычно заменяют день слепого поиска по логам.

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

Постоянное профилирование в продакшене и его допустимые границы

Продакшен требует режима, который не ломает сервис. Встроенный рекордер это позволяет: непрерывная запись с пресетом по умолчанию стоит единицы процентов процессора, буфер ограничен объёмом и возрастом, выгрузка копирует окно в файл за секунды. Асинхронный профилировщик тоже рассчитан на живые системы, но с оговорками. Для разрешения нативных кадров иногда нужны отладочные символы библиотеки виртуальной машины, а режим внешних счётчиков зависит от параметра ядра perf_event_paranoid, и в контейнерах доступ к нему по умолчанию закрыт. Внутри контейнера утилите нужен идентификатор процесса из того же пространства имён и те же права, что и у приложения, иначе подключение агента не пройдёт. Выгрузки не пишут на общий диск вслепую: файл записи занимает сотни мегабайт, у него прописывают отдельную полку с ограничением времени хранения, иначе серией срочных выгрузок заканчивается место в разделе с логами.

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

Вопросы, которые остаются за лабораторными замерами

Две среды отвечают на разные вопросы, и подмена одного другим дорого обходится. Живой профиль показывает, где время, но не объясняет, почему завтра стало лучше: изменение смеси трафика легко перевешивает выгоду от удачной правки. Лаборатория держит переменные под контролем, и только в ней честно работают сравнения до и после. Для отдельных горячих методов выпуски JDK дают отдельный ответ в виде бенчмарков JMH, и находка из продакшена, оформленная в такой тест, остаётся в репозитории навсегда:

@State(Scope.Benchmark)
@BenchmarkMode(Mode.AverageTime)
public class SumBench {

    @Benchmark
    public long sum() {
        return IntStream.range(0, 10_000_000).sum();
    }
}

Пороговые значения для таких бенчмарков берут из живого профиля: если метод тратит в продакшене сто двадцать микросекунд, тест с циклом из тысячи итераций не заметит его деградации. Разумный цикл выглядит так: сигнал из метрик, гипотеза из профилей продакшена, подтверждение на стенде, регрессионный тест в конвейере. Инцидент закрыт не тогда, когда сервис стал быстрее, а когда воспроизведение тормоза поселилось в автоматическом наборе. А устойчивая разница между тридцатью миллисекундами и секундой с хвостом лечится только парой глаз, которые смотрят в правильную сторону.