DIY do-it-yourself instrumentation profiler
I have long wanted to write a simple utility that would allow showing in which methods the code spends most of the time, which objects and in what quantity it creates and quickly turn on the trace of the method visit without modifying the source code.
Basic requirements - simplicity, the ability to run in text mode, and independence from the architecture.
In most java machines, there is a Java Virtual Machine Tool Interface (JVM TI) .
But this interface involves writing a native module, so it was not considered.
')
The possibility of instrumentation (intstrumentation) of bytecode remains.
The standard java.lang.instrument package allows you to intervene in the process of loading the bytecode with the possibility of changing it on the fly.
It looks like this:
When starting a java machine, the -javaagent key is specified: jar-file-name = parameters,
where jar-file-name is the full path to the agent jar file, parameters are the parameters passed to the agent.
The manifest file jar specifies the class containing the method
which jvm will call after the agent has loaded.
Details about this mechanism can be found here .
Our agent’s task is to change the methods of the loaded classes in such a way
so that when entering and exiting the method, the methods of our class TracerAgent were called :
An instance of the MethodInfo class contains information about the method.
It is necessary to store MethodInfo somewhere for each instrumented method.
For this, for each class a shadow class is created of the following form:
Since the shadow fields of the class are static, they are initialized automatically at boot. The following code is added to the beginning of each variable method:
In the end
The Javassist library is used to modify and create bytecode. Allows you not to focus on bytecode, but to write code modifications on java.
Now, when entering and exiting the method, control will be intercepted and
passed to the corresponding methods of the MethodCallProcessor class.
MethodCallProcessor stores a call stack for each thread using ThreadLocal.
methodEnter saves the MethodCallMarker stack over time for a call and increases the call count.
If the method call needs to be traced, then the call stack is displayed.
methodExit selects MethodCallMarker from the stack, and adds the time spent in the method to its MethodInfo.
In the TracerAgent constructor, a thread is created and registered with the shutdownhook. This thread will be launched during shutdown sequence jvm and prints the collected statistics. The Thread of periodic statistics output is also created and launched there.
Sample run for the code from the article
javassist does not always cope with the new bytecode format class files version 51.
the -XX switch : -UseSplitVerifier disables the new bytecode verifier entered in JVM7, details .
Naturally, the call to the agent methods could not but affect the speed.
As you can see, the work time has increased almost 500 times.
But this is an extreme case, where methods with an almost empty body are called, in ordinary life you can put up with an overhead projector.
The goal is not so much accurate profiling by time, as an exact number of calls,
created objects and traceability. The code is available on github .
Ps. You should not consider the resulting code as a ready profiler commercial level. This is nothing more than an experiment revealing another mechanism for the operation of the JVM.
Basic requirements - simplicity, the ability to run in text mode, and independence from the architecture.
In most java machines, there is a Java Virtual Machine Tool Interface (JVM TI) .
But this interface involves writing a native module, so it was not considered.
')
The possibility of instrumentation (intstrumentation) of bytecode remains.
The standard java.lang.instrument package allows you to intervene in the process of loading the bytecode with the possibility of changing it on the fly.
It looks like this:
When starting a java machine, the -javaagent key is specified: jar-file-name = parameters,
where jar-file-name is the full path to the agent jar file, parameters are the parameters passed to the agent.
The manifest file jar specifies the class containing the method
public static void premain(String args, Instrumentation instrumentation) which jvm will call after the agent has loaded.
Details about this mechanism can be found here .
Our agent’s task is to change the methods of the loaded classes in such a way
so that when entering and exiting the method, the methods of our class TracerAgent were called :
@SuppressWarnings("unused") public static void methodEnter(MethodInfo methodInfo) { methodCallProcessor.methodEnter(methodInfo); } @SuppressWarnings("unused") public static void methodExit() { methodCallProcessor.methodExit(); } An instance of the MethodInfo class contains information about the method.
It is necessary to store MethodInfo somewhere for each instrumented method.
For this, for each class a shadow class is created of the following form:
public class ShadowClassXXX { public static MethodInfo m1 = agent.TracerAgent.getMethodInfo(1L); // MethodInfo /* .. */ public static MethodInfo m99 = agent.TracerAgent.getMethodInfo(99L); // MethodInfo } Since the shadow fields of the class are static, they are initialized automatically at boot. The following code is added to the beginning of each variable method:
TracerAgent.methodEnter(ShadowClass.mXXX); In the end
TracerAgent.methodExit(); The Javassist library is used to modify and create bytecode. Allows you not to focus on bytecode, but to write code modifications on java.
Now, when entering and exiting the method, control will be intercepted and
passed to the corresponding methods of the MethodCallProcessor class.
MethodCallProcessor stores a call stack for each thread using ThreadLocal.
methodEnter saves the MethodCallMarker stack over time for a call and increases the call count.
If the method call needs to be traced, then the call stack is displayed.
methodExit selects MethodCallMarker from the stack, and adds the time spent in the method to its MethodInfo.
In the TracerAgent constructor, a thread is created and registered with the shutdownhook. This thread will be launched during shutdown sequence jvm and prints the collected statistics. The Thread of periodic statistics output is also created and launched there.
Options: -javaagent: <full path to the agent jar file> = p: regexp [#t: regexp] [# d: number] [# i: number] p - instrumented classes (full match - match) t - traced methods (partial match - find) d - debug level i - statistics output period in seconds (0 disables periodic output)
Sample run for the code from the article
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:\traceragent\target\traceragent-1.0-SNAPSHOT-complete.jar=p:examples.*#d:1#i:5 javassist does not always cope with the new bytecode format class files version 51.
the -XX switch : -UseSplitVerifier disables the new bytecode verifier entered in JVM7, details .
result
[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)
10,000,000 examples.data.CashAccountRow.setGender (int)
10,000,000 examples.data.CashAccountRow.setAge (int)
10,000,000 examples.data.CashAccountRow.setAmount (int)
10,000,000 examples.data.CashAccountRow.setHeight (int)
10,000,000 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 ***
Naturally, the call to the agent methods could not but affect the speed.
As you can see, the work time has increased almost 500 times.
But this is an extreme case, where methods with an almost empty body are called, in ordinary life you can put up with an overhead projector.
The goal is not so much accurate profiling by time, as an exact number of calls,
created objects and traceability. The code is available on github .
Ps. You should not consider the resulting code as a ready profiler commercial level. This is nothing more than an experiment revealing another mechanism for the operation of the JVM.
Source: https://habr.com/ru/post/185010/
All Articles