Управление Java Flight Recorder

Не так давно в мире Java случилось грандиозное событие. Во всех актуальных версиях OpenJDK стал доступен Java Flight Recorder (или просто JFR).

Раньше этот механизм был доступен только в коммерческих версиях Java от корпорации Oracle версии 8 и более ранних. В какой-то момент его реимплементировали с нуля в OpenJDK 12, затем бекпортировали в OpenJDK 11, которая является LTS-версией. Однако вот OpenJDK 8 оставалась за бортом этого праздника жизни. Вплоть до выхода апдейта 8u272, в который наконец-то тоже бекпортировали JFR. Теперь все (за редким исключением) пользователи OpenJDK могут начинать использовать эту функциональность.

Но вот незадача: большая часть документации в интернете относится к старой, коммерческой, версии JFR и во многом не соответствует версии, которая присутствует в OpenJDK. Да и та, что есть, весьма скудная и не способствует пониманию того, как это всё использовать.

В предлагаемой вашему вниманию статье я расскажу, как управлять работой JFR и как его настраивать.

Активация через параметры JVM

Активировать JFR можно несколькими путями. Один из них – задать соответствующие параметры при запуске Java-приложения. Для этого необходимо использовать два параметра:

• -XX:StartFlightRecording (активирует JFR и определяет основные параметры его работы),
• -XX:FlightRecorderOptions (задаёт дополнительные параметры работы).

Каждая из этих опций может быть дополнена настройками, например:

java -XX:StartFlightRecording=filename=/path/to/record/file.jfr

или

java -XX:StartFlightRecording:filename=/path/to/record/file.jfr

задаёт путь к файлу, куда будет записана вся собранная JFR информация после завершения записи (или остановки приложения).

Опций может быть несколько. В таком случае они разделяются запятыми (без пробелов!).

Посмотрим, какие есть настройки у каждой из этих опций и для чего они нужны.

XX:StartFlightRecording

Посмотреть список опций можно в первоисточнике. В исходном файле OpenJDK. Для OpenJDK 11 это файл src/hotspot/share/jfr/dcmd/jfrDcmds.cpp.

XX:FlightRecorderOptions

Посмотреть список опций можно в исходном файле src/hotspot/share/jfr/recorder/service/jfrOptionSet.cpp.

Примеры использования

Минимально возможный пример запуска Java с JFR выглядит так:

java -XX:StartFlightRecording -version

В результате в консоль будет выдано сообщение:

Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 4787 JFR.dump name=1 filename=FILEPATH to copy recording data to file.
openjdk version "1.8.0_275"
OpenJDK Runtime Environment (build 1.8.0_275-b01)
OpenJDK 64-Bit Server VM (build 25.275-b01, mixed mode)

Тут мы видим, что, помимо версии Java, запрашиваемой параметром -version, выведены ещё две строки:

• сообщение о том, что JFR запущен и с каким идентификатором,
• подсказка, как получить результаты работы JFR через утилиту jcmd.

В параметрах мы не указали никаких настроек. Т.о., в силу быстрого завершения выполнения (сразу после вывода версии Java) мы не сможем получить результаты в виде файла. Данные JFR будут накапливаться в памяти и пропадут при остановке приложения.

Чтобы это исправить, можно задать дополнительные опции:

java -XX:StartFlightRecording=filename=recording.jfr -version

В результате по окончании работы приложения записанные данные будут сброшены в файл recording.jfr в текущем каталоге.

Вместо имени файла, можно указать имя каталога:

java -XX:StartFlightRecording=filename=./ -version

Тогда имя конкретного файла будет сгенерировано в момент записи, например: hotspot-pid-16330-id-1-2020_11_30_17_16_49.jfr. Это может быть полезно, если запускается много экземпляров JVM и не хочется перетирать данные предыдущих запусков.

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

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

java \
  -XX:StartFlightRecording=disk=true,maxsize=10g,maxage=24h,filename=./recording.jfr \
  -XX:FlightRecorderOptions=repository=./diagnostics/,maxchunksize=50m,stackdepth=1024 \
  -jar application.jar

Прежде всего необходимо установить опцию disk=true, чтобы переключить JFR из режима записи в память в режим записи на диск.

Далее необходимо указать каталог, в который будет производиться запись: repository=./diagnostics/. В этом каталоге начнут появляться файлы с фрагментами записи данных JFR. Размер каждого такого отдельного фрагмента задаётся опцией maxchunksize=50m, но не стоит обманываться. Этот параметр задаёт размер чистых данных JFR, но в каждый файл в конце будет дописываться ещё довольно много служебной информации, что в отдельных случаях может увеличить размер файла в разы. Зато каждый такой файл будет самодостаточным и доступным для независимого изучения.

По умолчанию файлы будут писаться до бесконечности, пока приложение не остановится. Но, если оно будет работать достаточно долго, место на диске может закончиться. Чтобы этого не произошло, можно ограничить количество сохраняемых данных по времени (maxage=24h) или объёму (maxsize=10g). Если один из этих параметров будет превышен, то старые файлы в каталоге ./diagnostics/ начнут стираться.

Ну и последний параметр из приведённого ранее примера — stackdepth=1024. Он необходим для приложений с глубокими стеками вызовов, чтобы стек захватывался полностью.

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

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

Файл конфигурации профиля JFR

По умолчанию с OpenJDK поставляется два преднастроенных профиля:

• default.jfc (предназначен для мониторинга приложений на проде и дающий пенальти около 1% производительности),
• profile.jfc (предназначен для профилирования приложений на проде и дающий пенальти около 2% производительности и значительно больший объём снимаемых данных (больший размер jfr файлов).

Оба профиля тщательно подобраны разработчиками OpenJDK и лежат в каталоге JAVA_HOME/jre/lib/jfr для OpenJDK 8 или JAVA_HOME/lib/jfr для OpenJDK 11+.

Активировать их можно с помощью опции, например settings=profile.jfc:

java -XX:StartFlightRecording=settings=profile.jfc -version

Во многих ситуациях этого может оказаться достаточно, но не во всех. Дело в том, что в этих двух профилях остаётся отключённым очень большое количество метрик, которые могут очень помочь в тех или иных ситуациях. Например, в default.jfc практически отключён сбор информации о потреблении памяти, хотя он не даёт заметного пенальти, но при этом весьма полезен для понимания того, куда расходуется память приложения.

Т.о., становится понятно, что для своих частных случаев имеет смысл формировать отдельный, специально заточенный под себя файл с настройками. Но править его вручную – дело неблагодарное. Поэтому рекомендуется воспользоваться инструментом Java Mission Control (JMC), который умеет не только просматривать файлы, записанные JFR, но и управлять профилями записи этих файлов.

Скачать дистрибутив JMC можно, например, с сайта компании BellSoft.

Если мы запустим JMC и выберем пункт меню Window -> Flight Recording Template Manager, то попадём в окно управления настройками профилей записи JFR:

По умолчанию тут будут представлены два профиля, поставляемые с OpenJDK. Но мы можем создать свой профиль, если сначала продублируем имеющийся профиль с помощью кнопки Duplicate, а потом выберем копию и нажмём кнопку Edit:

В открывшемся окне можно задать название профиля, его описание и настройки в упрощённом виде.

Но если упрощённых настроек не хватает, можно перейти в подробный режим, нажав кнопку Advanced:

Перейдя в такой режим настроек, можно включить дополнительные метрики для записи. Например, можно включить метрики:

• ObjectAllocationInNewTLAB
• ObjectAllocationOutsideTLAB

Как показано на скриншоте выше. Значимого пенальти по скорости это не создаёт, зато позволяет оценить, где и чем мусорит приложение в памяти, что часто позволяет находить весьма нетривиальные проблемы.

Также важно понимать, что если были внесены и сохранены какие-либо изменения в этом окне, доступ к простому виду настроек будет потерян. Настройки всегда будут открываться только в подробном виде.

После создания своего профиля работы JFR его можно экспортировать в отдельный файл и использовать в настройках запуска, указав путь к этому файлу:

java -XX:StartFlightRecording=settings=/path/to/custom/profile.jfc -version

Управление JFR через командную строку (jcmd)

Но что делать, если приложение уже работает и надо запустить запись JFR? Или приостановить запись по какой-то причине? Или ещё что-то сделать?

Для этого можно воспользоваться штатной утилитой OpenJDK — jcmd. Например, запустить JFR можно следующей командой:

jcmd <pid> JFR.start duration=60s filename=myrecording.jfr settings=/path/to/custom/profile.jfc

Где <pid> — PID процесса JVM, в котором необходимо запустить JFR. В ответ будет выдана информация о том, что JFR запущено и куда именно будет записан файл с результатом:

19380:
Started recording 2. The result will be written to:

/media/data/java/OpenJDK/lmc7.1.1/myrecording.jfr

Данная команда запускает запись JFR на 60 секунд и указывает на то, чтобы записать результат в файл myrecording.jfr. Причём при таком указании файл будет записан по пути, локальному относительно не каталога запуска jcmd, а каталога, из которого была запущена JVM, в которой запускается JFR.

В целом видно, что при использовании jcmd доступны все те же самые опции, что и при запуске через параметры JVM, но некоторые опции имеют другие имена, поэтому далее они будут рассмотрены подробнее.

Также в ответе jcmd видна цифра 2. Это имя записи. Если мы в дальнейшем захотим как-то повзаимодействовать с этой записью, нам необходимо будет использовать данное имя. Например, вот так можно остановить запись:

jcmd <pid> JFR.stop name=2

Утилита jcmd может выполнять несколько команд, связанных с JFR. Рассмотрим их по порядку.

JFR.start

Запускает запись JFR с заданным именем, аналогично параметру запуска JVM -XX:StartFlightRecording. Если имя явно не задано, оно генерируется автоматически и выводится в консоль.

Можно использовать следующие опции:

JFR.configure

Настраивает запись JFR аналогично параметру -XX:FlightRecorderOptions. Данная команда должна выполняться перед JFR.start, чтобы изменения вступили в силу.

JFR.stop

Останавливает запись и сбрасывает записанные данные в файл, указанный при старте или непосредственно при вызове данной команды.

JFR.dump

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

JFR.check

Выводит информацию об активных записях JFR. Данная команда полезна, чтобы понять, запущена ли уже запись JFR в JVM и требуется ли её запускать или можно смотреть информацию в уже запущенной. А также чтобы убедиться, что записываются интересуемые события (метрики) JFR.

Примеры использования

Разберём типовой сценарий использования jcmd для работы с JFR.

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

Прежде всего посмотрим, не запущена ли уже запись JFR:

jcmd <pid> JFR.check

Получаю результат:

vektor@work$ jcmd 28534 JFR.check
28534:
Recording 1: name=JMC_Default maxsize=100,0MB (running)

Видно, что уже запущена запись с именем JMC_Default.

Допустим, мне необходимо посмотреть, как расходуется куча JVM. Как понять, снимается данная информация в запущенной записи или нет? Для этого можно посмотреть подробную информацию и найти в ней настройки для jdk.ObjectAllocationInNewTLAB и jdk.ObjectAllocationOutsideTLAB. Выполняем:

jcmd <pid> JFR.check name=JMC_Default verbose=true

И получаем результат (сокращено для наглядности):

vektor@work$ jcmd 28534 JFR.check name=JMC_Default verbose=true
28534:
Recording 1: name=JMC_Default maxsize=100,0MB (running)

 Flight Recording (jdk.ActiveRecording)
   [enabled=true]
 Recording Setting (jdk.ActiveSetting)
...
 Allocation in new TLAB (jdk.ObjectAllocationInNewTLAB)
   [enabled=false,stackTrace=true]
 Allocation outside TLAB (jdk.ObjectAllocationOutsideTLAB)
   [enabled=false,stackTrace=true]
...

Видно, что интересующие меня метрики отключены. Но не беда: можно запустить отдельную запись в том же процессе JVM с интересующими меня настройками:

jcmd <pid> JFR.start \
  name=memory_profile \
  duration=10m \
  filename=/path/to/recording.jfr \
  settings=/path/to/memory_profile.jfc

И получим вывод:

vektor@work$ jcmd 28534 JFR.start name=memory_profile duration=10m filename=/path/to/recording.jfr settings=/path/to/memory_profile.jfc
28534:
Started recording 4. The result will be written to:

/path/to/recording.jfr

Видно, что запись успешно запустилась.

Также можно посмотреть список всех записей:

jcmd <pid> JFR.check

И убедиться, что наша запись работает параллельно с ранее запущенной:

vektor@work$ jcmd 28534 JFR.check
28534:
Recording 1: name=JMC_Default maxsize=100,0MB (running)

Recording 4: name=memory_profile duration=10m (running)

Через 10 минут мы получим файл с результатами записи, который готов к открытию и изучению в Java Mission Control.

Но что делать, если есть необходимость включить запись на постоянной основе и иметь возможность анализировать результаты за сутки или более? В таком случае памяти на все записываемые данные может не хватить, а значит, нужно активировать их сброс на диск по мере записи. Для этого можно предварительно выполнить команду:

jcmd 28534 JFR.configure repositorypath=/path/to/disk/cahce maxchunksize=20m

Таким образом мы зададим каталог, куда будет скидываться записываемая информация. Плюс мы устанавливаем размер одного файла. Т.е. данные будут писаться фрагментами по 20 Мб, каждый из которых будет самодостаточным, и его можно будет просматривать в JMC независимо от всех остальных файлов.

В результате выполнения команды увидим следующий ответ:

vektor@work$ jcmd 28534 JFR.configure repositorypath=/path/to/disk/cahce maxchunksize=20m
28534:
Repository path: /path/to/disk/cahce/2020_12_03_16_58_40_28534

Max chunk size: 20,0 MB

Т.е. настройки установлены успешно. Теперь можно запускать непрерывную запись JFR:

jcmd 28534 JFR.start \
  name=continuouse_record \
  disk=true \
  maxage=24h \
  maxsize=10g \
  settings=/path/to/memory_profile.jfc

Самым главным моментом в данном примере является включение записи на диск, вместо хранения данных в памяти. Также ограничиваем максимальное время хранения данных одними сутками, а размер – 10 Гб. Как минимум для того, чтобы диск не переполнился.

После этого в каталоге /path/to/disk/cahce/2020_12_03_16_58_40_28534 начнут появляться файлы с записанными данными. А при превышении ограничений по времени или размеру старые файлы будут стираться.

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

jcmd 28534 JFR.dump \
  name=continuouse_record \
  begin=-10m \
  filename=/path/to/recording.jfr

В результате получим вывод:

vektor@work$ jcmd 28534 JFR.dump name=continuouse_record begin=-10m filename=/path/to/recording.jfr
28534:
Dumped recording "continuouse_record", 13,1 MB written to:

/path/to/recording.jfr

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

Заключение

В данной статье мы рассмотрели, как можно управлять записью Java Flight Recorder, и актуальный набор параметров для этого.

За скобками осталось ещё очень много интересного, т. к. управлять записью можно ещё и программно. А также добавлять свои типы событий и метрик, а потом анализировать всю собранную информацию в Java Mission Control.

Но это всё уже темы для других статей.

А тем, кого интересует, как использовать JFR для анализа и оптимизации приложения, я рекомендую серию статей от Алексея Рагозина:

• JDK Flight Recorder – a gem hidden in OpenJDK
• Hunting down code hotspots with JDK Flight Recorder
• Hunting down memory issues with JDK Flight Recorder