Вчера разбирался с забористым багом — барахлила асинхронная связь между двумя модулями приложения (на одной 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, но давайте останемся в рамках приличия 🤭