В продолжение темы про JFR ✈️
Вчера разбирался с забористым багом — барахлила асинхронная связь между двумя модулями приложения (на одной JVM): один обновлялся, а второй не всегда. Помимо нестабильности воспроизведения дело усложнялось тем, что проблема стреляла
только на удалённом сервере заказчика. Короче, всё по классике😏
При помощи ряда экспериментов, интуиции и такой-то матери мне удалось выяснить, что один из асинхронно выполняемых методов прерывается из-за какого-то исключения. Но этого исключения
не было в логах, потому что в методе не предусмотрели
try/catch, а сам метод вызывался так:
executorService.submit(this::fireBatchedEvents)
, то есть отправлялся на исполнение в пул безо всякой обратной связи (что уже не хорошо, но это отдельная тема✍️)
И вот ситуация:
— исключение есть
— логов нет
— добавить логирование в код нельзя, потому что после перезапуска проблема опять перестанет повторяться.
"И как теперь что?" 🫤 (© Масяня)
К счастью, внутри JVM на выбросы исключений заведено отдельное событие для JDK Flight Recorder, оно называется
jdk.JavaExceptionThrow. Если его включить и провести запись JFR во время проявления проблемы, то в ней (в записи) должны осесть данные обо всех исключениях, даже если само приложение их "глотает" 😋
Запуск записи в моём случае выглядел так:
./jattach <PID> jcmd JFR.start settings=none +jdk.JavaExceptionThrow#enabled=true +jdk.JavaExceptionThrow#stackTrace=true
, где:
•
jattach —
утилита для подключения к JVM, когда под рукой только JRE, а не JDK (в частности, нет
jcmd);
•
jcmd JFR.start settings=none — команда на старт записи с полностью выключенными событиями (чтобы не писать лишнего);
•
+jdk.JavaExceptionThrow#enabled=true — флаг включения события
JavaExceptionThrow. Символ "+" здесь нужен потому, что мы не
меняем значение какой-то настройки из параметра
settings (там же
none), а
добавляем его;
•
+jdk.JavaExceptionThrow#stackTrace=true — флаг добавления стектрейсов к регистрируемым событиям; по умолчанию он снят, а без стектрейсов смотреть на исключения скучно.
После старта записи я выполнил в приложении проблемное действие, а потом остановил запись вот таким заклинанием:
./jattach <PID> jcmd JFR.stop name=1 filename=error.jfr
, где:
•
jcmd JFR.stop name=1 — команда на останов конкретной записи (их может быть несколько). Имя записи можно либо задать явно при её запуске, либо посмотреть назначенное в ответе команды
JFR.start 🚀
На выходе получился файл
error.jfr, открыв который в
Java Mission Control, удалось быстро отыскать пропавшее исключение и, главное, увидеть его стектрейс (хотя всего их там оказалось аж 320😳)
Кажется, это неплохой пример применения JFR в сложной ситуации. Если бы не помог и он, можно было бы расчехлить
BTrace, но давайте останемся в рамках приличия 🤭