With a system running 24/7, you have to make sure that it performs well at any time of the day. Several commercial solutions exist to monitor the performance of systems: NewRelic, GraphDat and many others. They allow to see for instance if the api call response time change week after week or after each release of the project. So the developers can easily spot where the bottlenecks are and fix them.
You can also use profilers such as JProfiler,YourKit, … to detect bottlenecks, memory leaks, thread leaks, …
Most of those tools works by using a java agent, a pluggable library that runs embedded in a JVM that intercepts the classloading process. By modifying the classloading process, they can dynamically change the classes instructions to perform method logging, performance measure, …
In this post we are going to describe how to implement a simple java agent to measure how frequently and how long some methods of your application take and publish the results to JMX and to Graphite.
We will use the following technologies:
- javassist: library to manipulate java bytecode
- coda hale metrics: library that provides classes to measure time and compute average time, mean rate, percentiles, …
To follow the instructions in this post, you would need:
- jdk >= 1.6
- maven
- graphite, a scalable realtime graphing (optional). If you are interested to install it on Ubuntu, you can look athttps://gist.github.com/jgeurts/3112065
You can get the code presented in this post from github:
git clone https://github.com/fredang/agent-metric-example.git
Agent
To start a JVM with a specific agent, you just need to pass a special parameter to the java program:
java -javaagent:<agent.jar>=<agent_arguments> <mainClass> |
At startup, the JVM invokes the method premain of the agent class with the argument of the agent and the Instrumentation class that we can use to apply some code transformation. It knows which class in the jar file to use by looking at the file MANIFEST.MF.
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
|
public class MetricAgent { private final static Logger logger = LoggerFactory.getLogger(MetricAgent.class); public static void premain(String agentArguments, Instrumentation instrumentation) { RuntimeMXBean runtimeMxBean = ManagementFactory.getRuntimeMXBean(); logger.info("Runtime: {}: {}", runtimeMxBean.getName(), runtimeMxBean.getInputArguments()); logger.info("Starting agent with arguments " + agentArguments); MetricReporter.startJmxReporter(); if (agentArguments != null) { // parse the arguments: // graphite.host=localhost,graphite.port=2003 Map<String, String> properties = new HashMap<String, String>(); for(String propertyAndValue: agentArguments.split(",")) { String[] tokens = propertyAndValue.split(":", 2); if (tokens.length != 2) { continue; } properties.put(tokens[0], tokens[1]); } String graphiteHost = properties.get("graphite.host"); if (graphiteHost != null) { int graphitePort = 2003; String graphitePrefix = properties.get("graphite.prefix"); if (graphitePrefix == null) { graphitePrefix = "test"; } String graphitePortString = properties.get("graphite.port"); if (graphitePortString != null) { try { graphitePort = Integer.parseInt(graphitePortString); } catch (Exception e) { logger.info("Invalid graphite port {}: {}", e.getMessage()); } } MetricReporter.startGraphiteReporter(graphiteHost, graphitePort, graphitePrefix); } } // define the class transformer to use instrumentation.addTransformer(new TimedClassTransformer()); }} |
In this agent, we are using a MetricReporter to compute and publish the measures to JMX and Graphite by using the coda hale metrics library:
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
|
public class MetricReporter { private final static Logger logger = LoggerFactory.getLogger(MetricReporter.class); private static MetricRegistry metricRegistry = new MetricRegistry(); public static void startJmxReporter() { logger.info("Init JMX reporter"); JmxReporter jmxReporter = JmxReporter .forRegistry(metricRegistry) .convertDurationsTo(TimeUnit.MILLISECONDS) .convertRatesTo(TimeUnit.MINUTES) .build(); jmxReporter.start(); } public static void startGraphiteReporter(String host, int port, String prefix) { logger.info("Init Graphite reporter: host={}, port={}, prefix={}", host, port, prefix); Graphite graphite = new Graphite(new InetSocketAddress(host, port)); GraphiteReporter graphiteReporter = GraphiteReporter.forRegistry(metricRegistry) .prefixedWith(prefix) .build(graphite); graphiteReporter.start(1, TimeUnit.MINUTES); } // called by instrumented methods public static void reportTime(String name, long timeInMs) { Timer timer = metricRegistry.timer(name); timer.update(timeInMs, TimeUnit.MILLISECONDS); }} |
Coda Hale Metrics provides several class to measure times. Here, we are using the Timer class. Each time we want to log a measure, we invoke the method Timer.update with the time it took to execute an action. And the class takes care of computing the mean time of the executions, the mean rate, the min, the max, …
In the agent code, we add a code transformer(TimedClassTransformer) to transform all the classes loaded by the classLoader.
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
|
public class TimedClassTransformer implements ClassFileTransformer { private final static Logger logger = LoggerFactory.getLogger(TimedClassTransformer.class); private ClassPool classPool; public TimedClassTransformer() { classPool = new ClassPool(); classPool.appendSystemPath(); try { classPool.appendPathList(System.getProperty("java.class.path")); // make sure that MetricReporter is loaded classPool.get("com.chimpler.example.agentmetric.MetricReporter").getClass(); classPool.appendClassPath(new LoaderClassPath(ClassLoader.getSystemClassLoader())); } catch (Exception e) { throw new RuntimeException(e); } } public byte[] transform(ClassLoader loader, String fullyQualifiedClassName, Class<?> classBeingRedefined, ProtectionDomain protectionDomain, byte[] classBytes) throws IllegalClassFormatException { String className = fullyQualifiedClassName.replace("/", "."); classPool.appendClassPath(new ByteArrayClassPath(className, classBytes)); try { CtClass ctClass = classPool.get(className); if (ctClass.isFrozen()) { logger.debug("Skip class {}: is frozen", className); return null; } if (ctClass.isPrimitive() || ctClass.isArray() || ctClass.isAnnotation() || ctClass.isEnum() || ctClass.isInterface()) { logger.debug("Skip class {}: not a class", className); return null } boolean isClassModified = false; for(CtMethod method: ctClass.getDeclaredMethods()) { // if method is annotated, add the code to measure the time if (method.hasAnnotation(Measured.class)) { try { if (method.getMethodInfo().getCodeAttribute() == null) { logger.debug("Skip method " + method.getLongName()); continue; } logger.debug("Instrumenting method " + method.getLongName()); method.addLocalVariable("__metricStartTime", CtClass.longType); method.insertBefore("__metricStartTime = System.currentTimeMillis();"); String metricName = ctClass.getName() + "." + method.getName(); method.insertAfter("com.chimpler.example.agentmetric.MetricReporter.reportTime("" + metricName + "", System.currentTimeMillis() - __metricStartTime);"); isClassModified = true; } catch (Exception e) { logger.warn("Skipping instrumentation of method {}: {}", method.getName(), e.getMessage()); } } } if (isClassModified) { return ctClass.toBytecode(); } } catch (Exception e) { logger.debug("Skip class {}: ", className, e.getMessage()); } return classBytes;}} |
Every method annotated with @Measured are rewritten by adding code instruction before and after the original method code:
|
1
2
3
|
long __metricStartTime = System.currentTimeMillis();// original method codecom.chimpler.example.agentmetric.MetricReporter.reportTime(metricName, System.currentTimeMillis() - __metricStartTime); |
The last step is to define the file MANIFEST.MF and package the agent.
Content of the file MANIFEST.MF:
|
1
|
premain-Class: com.chimpler.example.agentmetric.MetricAgent |
Package the application:
cd agent mvn clean compile install assembly:single
Running a java program with the java agent
To test the agent, we are going to run the agent on the following program:
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
|
public class RunExample { private Random random = new Random(); public RunExample() { } @Measured public void doSleep() { try { Thread.sleep(10000); } catch (InterruptedException e) { } } @Measured private void doTask() { try { Thread.sleep(random.nextInt(1000)); } catch (InterruptedException e) { } } @Measured public void doWork() { for(int i = 0 ; i < random.nextInt(10) ; i++) { doTask(); } } public static void main(String[] args) { RunExample test = new RunExample(); while(true) { test.doWork(); test.doSleep(); } }} |
This program indefinitely calls the method doWork and doSleep.
To build the application:
cd agent-test mvn clean assembly:single
Now you can run the application with the agent:
If you don’t have graphite installed on your computer:
java -javaagent:../agent/target/metric-agent-jar-with-dependencies.jar
-cp target/agent-test-jar-with-dependencies.jar
com.chimpler.example.agentmetric.example.RunExample
If you have graphite installed:
java -javaagent:../agent/target/metric-agent-jar-with-dependencies.jar=graphite.host:localhost,graphite.port:2003,graphite.prefix:test
-cp target/agent-test-jar-with-dependencies.jar
com.chimpler.example.agentmetric.example.RunExample
You can see the metrics through JMX by using jconsole:
jconsole
And also on graphite:
As expected the average time execution of the method doTask is 500ms.
Coda hale metrics computes several metrics, below are the main measures:
- Count: number of times the method is called since the program starts
- Mean: mean execution time of the method
- Min: min execution time of the method
- Max: max execution time of the method
- MeanRate: number of times per minute the method was invoked
Conclusion
We have seen in this post how to write a simple agent to measure the number of times a method is invoked and the execution time the method.
The agent can be improved to log more informations, for instance log SQL queries executed through JDBC, log rest calls by users, …
Those metrics can be used to compare the performance of a system after each release deployment or to trigger alerts when the rate or execution time of a method goes above a threshold (by using nagios for instance).
In a word:
What: trace method's invocation times and execution time
How: java agent: java -javaagent:<agent.jar>=<agent_arguments> <mainClass>
Component:
a. Instrumentation is the addition of byte-codes to methods for the purpose of gathering data to be utilized by tools; use to apply some code transformation; It knows which class in the jar file to use by looking at the file MANIFEST.MF.: premain-Class: com.chimpler.example.agentmetric.MetricAgent
b. TimedClassTransformer: a code transformer to transform all the classes loaded by the classLoader.
c. Report or measure helper: MetricReporter, reportTime
process:
a. define agent, specify agent class in MANIFEST.MF: premain-Class: com.chimpler.example.agentmetric.MetricAgent
b. load wrapped class byte code to instrumentation
c. define measure helper
d. add measure helper to required class base on classpool
The premain (and not the agentmain) method is invoked first. The class file transformer is passed classes as they are loaded. The transformer chooses to redefine the User object prior to its use. Subsequently the classes loaded at shutdown also pass through the transformer.