Инструментирующий профайлер своими руками

Давно хотел написать простую утилиту, которая позволила бы показать в каких методах код проводит основное время, какие объекты и в каком количестве создает и оперативно включать трассировку посещения метода не модифицируя исходник.

Основные требования — простота, возможность запуска в текстовом режиме и независимость от архитектуры.

В большинстве java машин существует Java Virtual Machine Tool Interface (JVM TI) ^[1].
Но этот интерфейс предполагает написание 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 и вызовет после загрузки агента.
Подробно про этот механизм можно прочитать здесь ^[2].

Задача нашего агента состоит в изменении методов загружаемых классов таким образом,
что бы при входе и выходе из метода вызывались методы нашего класса TracerAgent ^[3]:

    @SuppressWarnings("unused")
    public static void methodEnter(MethodInfo methodInfo) {
        methodCallProcessor.methodEnter(methodInfo);
    }
    @SuppressWarnings("unused")
    public static void methodExit() {
        methodCallProcessor.methodExit();
    }

Экземпляр класса MethodInfo ^[4] содержит информацию о методе.
Нужно где то хранить 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 ^[5]. Позволяет не сосредотачиваться на байткоде, а писать код модификаций на java.

Теперь при входе и выходе из метода будет перехватываться управление и
передаваться соответствующим методам класса MethodCallProcessor.

MethodCallProcessor ^[6] хранит стэк вызовов для каждого потока используя ThreadLocal.
methodEnter сохраняет в стэк MethodCallMarker ^[7] со временем вызова и увеличивает счетчик вызовов.
Если вызов метода нужно трассировать, то выводится стэк вызовов.
methodExit выбирает из стэка MethodCallMarker, и добавляет время проведенное в методе к его MethodInfo.

В конструкторе TracerAgent ^[3] создается Thread и регистрируется в shutdownhook. Этот Thread будет запущен при shutdown sequence jvm и распечатает собранную статистику. Там же создается и запускается Thread периодического вывода статистики.

Параметры:
-javaagent:<полный путь к jar-файлу агента>=p:regexp[#t:regexp][#d:number][#i:number]
p - инструментируемые классы (полное совпадение - match)
t - трассируемые методы (частичное совпадение - find)
d - уровень отладки 
i - период вывода статистики в секундах (0 отключает периодический вывод)

Пример запуска для кода из статьи ^[8]:

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, подробности ^[9].

[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 ^[10].

PS. Не стоит рассматривать получившийся код как готовый профайлер коммерческого уровня. Это не более чем эксперимент, раскрывающий еще один механизм работы JVM.

Автор: xlix123

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