Отладка Java приложения, когда оно совсем не ждёт — добро пожаловать в InTrace подход

Доводилось ли вам когда-либо исследовать шаг за шагом выполние некого Java кода, который не удосужились снабдить средствами логирования или прочими механизмами наблюдения?
Усложним задачу тем, что не будем перекомпилировать исследуемый код, да и вообще перезапускать существующий процесс (тот случай, когда непонятное поведение было да и при перестарте сплыло). Java машина, конечно же, запущена с самыми обыкновенными опциями (без параметров для аттача дебагера или ещё каких наворотов).
А так хочется понять, что же происходит.

Именно этим мы и займёмся.

Для наглядного примера возьмём простой код, некоторое подобие реализации старой доброй всем известной сказки «Репка». Цель демонстрации ниже приведённого кода вовсе не показать красоту организации классов или методов, а тем более нейминга (тут, скорее, безобразие), а просто сделать ряд вызовов за вызовом.

     1: package skazka; 
     2: 
     3: import java.io.BufferedReader; 
     4: import java.io.InputStreamReader; 
     5: 
     6: public class Repka { 
     7:   public static void main(String[] args) throws Exception { 
     8:     new BufferedReader(new InputStreamReader(System.in)).readLine(); 
     9: 
    10:     try { 
    11:       new Dedka().tyanem("репка", 200); 
    12:     } catch (Exception ex) { 
    13:       processError(ex); 
    14:     } 
    15:     
    16:   } 
    17: 
    18:   public static boolean processError(Exception ex) { 
    19:     // ... 
    20:     return true; 
    21:   } 
    22: } 
    23: 
    24: class Dedka { 
    25:   void tyanem(String target, int weight) { 
    26:     new Babka().tyanem(target, weight - 15); 
    27:   } 
    28: } 
    29: 
    30: class Babka { 
    31:   void tyanem(String target, int weight) { 
    32:     new Vorona().tyanem(target, weight - 10); 
    33:   } 
    34: } 
    35: 
    36: class Vorona { 
    37:   void tyanem(String target, int weight) { 
    38:     if (!target.equals("сыр")) { 
    39:       throw new RuntimeException("Ворона ждёт от бога сыра"); 
    40:     } 
    41: 
    42:     // ... 
    43:   } 
    44: } 
    

Скомпилируем

javac skazka/Repka.java

И запустим

java skazka.Repka

Теперь необходимо как-то «вклиниться» в уже запущенный процесс и адаптировать код под свои нужды. Для этого великолепно подходит Java-агент созданный Мартином Робертсоном (за что ему много-много искренней благодарности), под названием InTrace mchr3k.github.io/org.intrace ^[1], позволяющий на лету внедряться в исполняемый код, снабжая его элементами трейсинга.

InTrace агент помещается в уже запущенный Java процесс парой простых способов (на выбор):
1) программным методом

public static void loadAgent(String pid, String agentFilePath) throws Exception {
    VirtualMachine vm = VirtualMachine.attach(pid);
    vm.loadAgent(agentFilePath, "");
    vm.detach();
}

Подсунув процессу джава-агент intrace-agent.jar из github.com/mchr3k/org.intrace/tree/master/binaries/jars/latest_development ^[2]

2) взяв VisualVM (скачав, если нет отсюда visualvm.java.net ^[3]) и пропатчив его (Tools->Plugins) InTrace плагином org-intrace-visualvm.nbm взятым из
github.com/mchr3k/org.intrace/tree/master/binaries/jars/latest_development ^[2]

Беда в том, что в org-intrace-visualvm.nbm не самые свежие файлы, поэтому найдите где VisualVM хранит плагины и подмените соответствующие джарники на более свежие из github.com/mchr3k/org.intrace/tree/master/binaries/jars/latest_development ^[2]
В моём случае (ОС Linux), следовало подменить
intrace-agent.jar на intrace-agent.jar и intrace-client-gui-linux.jar на intrace-ui.jar (см. скриншот ниже, плагин подсказывает пути)

Теперь остаётся запустить VisualVM, вызвать для skazka.Repka контекстное меню и выбрать «InTrace Application...», после чего увидим

жмём кнопку «Load InTrace Agent» и консоль доложит о внедрении InTrace текстом на подобие

Стадия внедрения благополучно завершена: в Java машине успешно поселился InTrace агент, готовый трансформировать байт код, снабжая его командами трейса, и докладывать результаты.

Переходим к стадии наблюдения за результатом, для чего запускаем инструмент управления агентом и анализа результатов (отдельное приложение).

Снова существует два простых варианта
1) мы внедряли агент первым «программным способом» тогда запускаем

java -jar intrace-ui.jar  

взятым тут
github.com/mchr3k/org.intrace/tree/master/binaries/jars/latest_development ^[2]
2) в случае использования VisualVM, нажимаем кнопку «Launch InTrace Client», и, в принципе, запустится абсолютно тот же файл, что и в первом примере (поскольку мы впатчили новый intrace-ui.jar)

Вбиваем адрес, настраиваем параметры трейса (я включил Entry/Exit+Branch+Args), жмём кнопку «Classes...» и указываем там skazka (это заставит добавить трейсинг в классы из пакета skazka).
Нажимаем «Enter» в консоли c запущенной «Репкой» (не забываем что именно этого она и ждёт для продолжения) и в конце концов получим на клиенте цепочку исполнения программы в виде вывода:

[21:52:39.861]:[1]:skazka.Dedka:<init>: {:24
[21:52:39.862]:[1]:skazka.Dedka:<init>: }:24
[21:52:39.862]:[1]:skazka.Dedka:tyanem: {:26
[21:52:39.865]:[1]:skazka.Dedka:tyanem: Arg (target): репка
[21:52:39.866]:[1]:skazka.Dedka:tyanem: Arg (weight): 200
[21:52:39.868]:[1]:skazka.Babka:<init>: {:30
[21:52:39.869]:[1]:skazka.Babka:<init>: }:30
[21:52:39.871]:[1]:skazka.Babka:tyanem: {:32
[21:52:39.871]:[1]:skazka.Babka:tyanem: Arg (target): репка
[21:52:39.871]:[1]:skazka.Babka:tyanem: Arg (weight): 185
[21:52:39.878]:[1]:skazka.Vorona:<init>: {:36
[21:52:39.878]:[1]:skazka.Vorona:<init>: }:36
[21:52:39.878]:[1]:skazka.Vorona:tyanem: {:38
[21:52:39.879]:[1]:skazka.Vorona:tyanem: Arg (target): репка
[21:52:39.879]:[1]:skazka.Vorona:tyanem: Arg (weight): 175
[21:52:39.879]:[1]:skazka.Vorona:tyanem: /:39
[21:52:39.885]:[1]:skazka.Vorona:tyanem: Throw:39: java.lang.RuntimeException: Ворона ждёт от бога сыра
	at skazka.Vorona.tyanem(Repka.java:39)
	at skazka.Babka.tyanem(Repka.java:32)
	at skazka.Dedka.tyanem(Repka.java:26)
	at skazka.Repka.main(Repka.java:11)

[21:52:39.885]:[1]:skazka.Vorona:tyanem: }:39
[21:52:39.886]:[1]:skazka.Repka:main: /:13
[21:52:39.890]:[1]:skazka.Repka:processError: {:20
[21:52:39.890]:[1]:skazka.Repka:processError: Arg (ex): java.lang.RuntimeException: Ворона ждёт от бога сыра
[21:52:39.891]:[1]:skazka.Repka:processError: Return: 1
[21:52:39.891]:[1]:skazka.Repka:processError: }:20
[21:52:39.891]:[1]:skazka.Repka:main: }:16

Каждая строка вывода описывается следующим форматом

[текущее время]:[идентификатор потока]:пакет:метод:дополнительная информация

где:
текущее время — говорит само за себя
идентификатор потока — уникальный идентификатор потока, разные потоки — разные числа (1, 2, 3, 4, ...)
пакет — пространство имён
метод — имя метода, в котором происходит выполнение
дополнительная информация — зависит от ситуации

Поддерживаемые виды трейса:
— входвыход метода

[21:52:39.861]:[1]:skazka.Dedka:<init>: {:24
[21:52:39.862]:[1]:skazka.Dedka:<init>: }:24

или

[21:52:39.890]:[1]:skazka.Repka:processError: {:20

— ветвления

[21:52:39.879]:[1]:skazka.Vorona:tyanem: /:39

— аргументы (отображение объектов идёт через toString() )

[21:52:39.865]:[1]:skazka.Dedka:tyanem: Arg (target): репка
[21:52:39.866]:[1]:skazka.Dedka:tyanem: Arg (weight): 200

-возвращаемые значения

[21:38:31.444]:[1]:skazka.Repka:processError: Return: 1

— исключения

[21:52:39.885]:[1]:skazka.Vorona:tyanem: Throw:39: java.lang.RuntimeException: Ворона ждёт от бога сыра
	at skazka.Vorona.tyanem(Repka.java:39)
	at skazka.Babka.tyanem(Repka.java:32)
	at skazka.Dedka.tyanem(Repka.java:26)
	at skazka.Repka.main(Repka.java:11)

В целом — всё что надо для успешного понимания ходы выполнения программы.

Потренируйтесь анализировать вывод на вышеприведённом примере (кое-что может быть сходу интуитивно не совсем понятно, но разобравшись быстро привыкаешь).

С наглядным примером, во что превращается код (как расставляются трейсы) можно ознакомиться на странице автора mchr3k.github.io/org.intrace/howintraceworks.html ^[4]

Также советую сразу обратить внимание на очень полезную кнопку «Filter...», которая помогает избавить от ненужного мусора

Существующая интеграция с Eclipse, позволяет запускать Java приложение с уже внедрённым InTrace агентом, выполнять настройку параметров трейсинга и анализировать результат работы. Более подробно смотрите тут mchr3k.github.io/org.intrace/eclipse.html ^[5]

ИТОГО

Преимущества:
1) Отслеживание хода выполнения программы на лету:
— вызовы методов, передаваемые аргументы, ветвления, генерируемые исключения,…
— без перекомпиляции и даже без перезапуска работающей программы
2) Доступен код (OpenSource)
3) Прост в настройке и использовании
4) Кроссплатформенное решение (Windows, Linux, ...)
5) Возможны интеграции с популярными инструментами разработки (Eclipse, VisualVM)

Недостатки:
1) Изменение байт кода на лету:
— страдает скорость выполнения (производительность)
— внедрение агента «мутирует» существующий процесс и он уже никогда не будет как прежде (в одну реку дважды не вступишь)
— модификации байт кода идут «как есть» и естественно «на свой страх и риск»
2) Нет массовой поддержки — всего один разработчик, но компенсируюется небольшим размером проекта и доступностью исходных кодов. Радует, что последний апдейт в репозитории был пару недель тому от публикации сего поста.
3) Продукт хорошо оттестирован на Java 1.6, но не тестирован на Java 1.7 (и с ней есть проблемы, см. багу github.com/mchr3k/org.intrace/issues/28 ^[6]). Насколько понимаю, автор пользуется только 1.6, писал «для себя» и совсем не для коммерции, уж кому надо поновее, не поленитесь взять и докрутить

В заключение: InTrace — агент, который определённо заслуживает знакомства как минимум, а, возможно, станет для вас незаменимым инструментом, раскрыв отладку джава приложений под другим углом, и, несомненно, кого-то выручит ещё не раз.

Учтя замечания и дополнения, стремлюсь раскрыть мощь InTrace (а также ряда других интересных агентов) в хабе JAVA и буду очень признателен за помощь.

Спасибо за внимание и обязательно поделитесь с теми, кого это может заинтересовать!

Автор: indality

Источник ^[7]