Давно хотел написать простую утилиту, которая позволила бы показать в каких методах код проводит основное время, какие объекты и в каком количестве создает и оперативно включать трассировку посещения метода не модифицируя исходник.
Основные требования — простота, возможность запуска в текстовом режиме и независимость от архитектуры.
В большинстве java машин существует Java Virtual Machine Tool Interface (JVM TI).
Но этот интерфейс предполагает написание native модуля, поэтому не рассматривался.
Остается возможность инструментирования (intstrumentation) байткода.
Стандартный пакет java.lang.instrument позволяет вмешаться в процесс загрузки байткода с возможностью его изменения на лету.
Выглядит это следующим образом:
При старте java машины указывается ключ -javaagent:jar-file-name=parameters,
где jar-file-name — это полный путь к jar файлу агента, parameters — параметры передаваемые агенту.
В манифесте jar файла указывается класс содержащий метод
public static void premain(String args, Instrumentation instrumentation)
который jvm и вызовет после загрузки агента.
Подробно про этот механизм можно прочитать здесь.
Задача нашего агента состоит в изменении методов загружаемых классов таким образом,
что бы при входе и выходе из метода вызывались методы нашего класса TracerAgent:
@SuppressWarnings("unused")
public static void methodEnter(MethodInfo methodInfo) {
methodCallProcessor.methodEnter(methodInfo);
}
@SuppressWarnings("unused")
public static void methodExit() {
methodCallProcessor.methodExit();
}
Экземпляр класса MethodInfo содержит информацию о методе.
Нужно где то хранить MethodInfo для каждого инструментированного метода.
Для этого для каждого класса создается shadow класс следующего вида:
public class ShadowClassXXX {
public static MethodInfo m1 = agent.TracerAgent.getMethodInfo(1L); // MethodInfo первого метода
/* .. */
public static MethodInfo m99 = agent.TracerAgent.getMethodInfo(99L); // MethodInfo последнего метода
}
Поскольку поля shadow класса статические, они инициализируются автоматически при загрузке. В начало каждого изменяемого метода добавляется код:
TracerAgent.methodEnter(ShadowClass.mXXX);
в конец
TracerAgent.methodExit();
Для модификации и создания байткода использована библиотека Javassist. Позволяет не сосредотачиваться на байткоде, а писать код модификаций на java.
Теперь при входе и выходе из метода будет перехватываться управление и
передаваться соответствующим методам класса MethodCallProcessor.
MethodCallProcessor хранит стэк вызовов для каждого потока используя ThreadLocal.
methodEnter сохраняет в стэк MethodCallMarker со временем вызова и увеличивает счетчик вызовов.
Если вызов метода нужно трассировать, то выводится стэк вызовов.
methodExit выбирает из стэка MethodCallMarker, и добавляет время проведенное в методе к его MethodInfo.
В конструкторе TracerAgent создается Thread и регистрируется в shutdownhook. Этот Thread будет запущен при shutdown sequence jvm и распечатает собранную статистику. Там же создается и запускается Thread периодического вывода статистики.
Параметры: -javaagent:<полный путь к jar-файлу агента>=p:regexp[#t:regexp][#d:number][#i:number] p - инструментируемые классы (полное совпадение - match) t - трассируемые методы (частичное совпадение - find) d - уровень отладки i - период вывода статистики в секундах (0 отключает периодический вывод)
Пример запуска для кода из статьи:
java -version
java version "1.7.0_21"
Java(TM) SE Runtime Environment (build 1.7.0_21-b11)
Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)
java -XX:-UseSplitVerifier -javaagent:D:traceragenttargettraceragent-1.0-SNAPSHOT-complete.jar=p:examples.*#d:1#i:5
javassist еще не всегда справляется с новым форматом байткода классфайлов версии 51.
ключ -XX:-UseSplitVerifier отключает новый верификатор байткода, введенный в JVM7, подробности.
[AGENT+] *** performance report ***
Top 5 time consuming methods (microseconds):
965050 examples.data.CashAccountRow$masks.access$100(examples.data.CashAccountRow$masks)
779944 examples.data.CashAccountRow.setAge(int)
766023 examples.data.CashAccountRow.setGender(int)
764292 examples.data.CashAccountRow.setHeight(int)
763387 examples.data.CashAccountRow.setAmount(int)
Top 5 called methods:
22805261 examples.data.CashAccountRow$masks.access$100(examples.data.CashAccountRow$masks)
9122242 examples.data.CashAccountRow$shifts.access$000(examples.data.CashAccountRow$shifts)
2280592 examples.data.CashAccountRow.setAge(int)
2280623 examples.data.CashAccountRow.setBitStorage(long)
2280653 examples.data.CashAccountRow.setGender(int)
Top 5 objects constructed:
1 examples.data.CashAccountStore
1 examples.data.CashAccountRow
[AGENT-] *** end of performance report ***
--- skip ---
Number of records matched:38
Elapsed time:7707ms
Used Memory:91MB
[AGENT+] *** performance report ***
Top 10 time consuming methods (microseconds):
36081913 examples.App.main(java.lang.String[])
20606259 examples.data.CashAccountStore()
15428502 examples.data.CashAccountStore.find2(examples.data.CashAccountStore$CashAccountFinder)
12439241 examples.data.GenMatcherAMOUNTHEIGHTGENDER.c(examples.data.CashAccountRow)
9469502 examples.data.CashAccountRow.getAmount()
5928018 examples.data.CashAccountRow$masks.access$100(examples.data.CashAccountRow$masks)
3392146 examples.data.CashAccountRow$shifts.access$000(examples.data.CashAccountRow$shifts)
3279163 examples.data.CashAccountRow.setAge(int)
3271959 examples.data.CashAccountRow.setHeight(int)
3267890 examples.data.CashAccountRow.setAmount(int)
Top 10 called methods:
140079808 examples.data.CashAccountRow$masks.access$100(examples.data.CashAccountRow$masks)
80079812 examples.data.CashAccountRow$shifts.access$000(examples.data.CashAccountRow$shifts)
40000000 examples.data.CashAccountRow.getAmount()
30000000 examples.data.CashAccountRow.setBitStorage(long)
20000000 examples.data.GenMatcherAMOUNTHEIGHTGENDER.c(examples.data.CashAccountRow)
10000000 examples.data.CashAccountRow.setGender(int)
10000000 examples.data.CashAccountRow.setAge(int)
10000000 examples.data.CashAccountRow.setAmount(int)
10000000 examples.data.CashAccountRow.setHeight(int)
10000000 examples.data.CashAccountRow.getBitStorage()
Top 10 objects constructed:
3 examples.data.CashAccountStore$CashAccountFinder$FieldGetter
3 examples.data.CashAccountStore$CashAccountFinder$PredicateHolder
3 examples.data.CashAccountRow
1 examples.data.GenMatcherAMOUNTHEIGHTGENDER
1 examples.data.GenMatcherBase
1 examples.data.CashAccountStore$CashAccountFinder$HeightFieldGetter
1 examples.data.CashAccountStore$CashAccountFinder
1 examples.data.CashAccountStore
1 examples.data.CashAccountStore$CashAccountFinder$AmountFieldGetter
1 examples.data.CashAccountStore$CashAccountFinder$GenderFieldGetter
[AGENT-] *** end of performance report ***
Естественно вызов методов агента не мог не сказаться на быстродействии.
Как видно время работы увеличилось почти в 500 раз.
Hо это экстремальный случай, где вызываются методы с практически пустым телом, в обычной жизни с оверхедом можно мириться.
Целью является не столько точный профайлинг по времени, сколько точное кол-во вызовов,
созданных объектов и возможность трассировки. Код доступен на GitHub.
PS. Не стоит рассматривать получившийся код как готовый профайлер коммерческого уровня. Это не более чем эксперимент, раскрывающий еще один механизм работы JVM.
Автор: xlix123
