Java Profiling with the java.lang.instrument Package
admin originally posted this on Wayne Adams' Blog.
Lately I've been looking at profilers and wondering how easy it would be to write one, mostly to be able to provide a little more sophisticated guidance to performance investigations. For example, while it is useful to pop a profiler and see what methods are consuming the most time in an application, wouldn't it be even more interesting if your profiler could generate an event any time your application spent more than a specified amount of time in a method, like 25% more than the average time (or fell more than 2 sigma outside the mean)?In general, getting events when something interesting happens is more helpful than watching a display and waiting for anomalies (how many monkeys does that employ?!). That's why I'm also a little disappointed in the JVM's built-in JMX beans, only two of which (MemoryMXBean and MBeanServerDelegateMBean) implement the NotificationEmitter interface. I would much prefer registering for notifications from the garbage collector JMX bean than triggering verbose gc output (with command-line options) and then following and parsing log output!
In this posting I'm going to show you how quickly you can instrument a Java application, and hopefully it will look easy enough that you will give it a try. First, I'd recommend reading the package documentation for java.lang.instrument. It isn't a large package and the time spent is well worth it.
As usual, let's get the setup out of the way. For pre-requisites (such as Java SDK, Maven, etc.), please see one of my earlier posts. Assuming you have the Java SDK and Maven 2 (along with the usual Maven environment variables created), you're ready to go. In a directory containing your development projects, enter the following:
mvn archetype:generate -DgroupId=com.example.profiler -DartifactId=JavaProfiler
Accept all the defaults and wait for your project directory to be generated.
Change into the new project directory, open the pom.xml file and add the following build plugins:
<build>
<plugins>
<plugin>
<artifactId>maven-compiler-plugin</artifactId>
<configuration>
<source>1.6</source>
<target>1.6</target>
</configuration>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-jar-plugin</artifactId>
<configuration>
<archive>
<manifestFile>src/main/resources/META-INF/MANIFEST.MF</manifestFile>
</archive>
</configuration>
</plugin>
</plugins>
</build>
The first plugin specifies Java SE6 (rather than the default 1.3!) and the second one says we're going to be supplying our own manifest file. More on that below.
Our basic profiler is responsible for doing a couple of things:
- It must supply a premain method, per the requirements discussed in the package documentation;
- It must implement the ClassFileTransformer interface (or delegate to a class which does; we're keeping it simple here).
package com.example.profiler;
import java.lang.instrument.ClassFileTransformer;
import java.lang.instrument.IllegalClassFormatException;
import java.lang.instrument.Instrumentation;
import java.security.ProtectionDomain;
/**
* Simple java.lang.instrument profiler
*
*/
public class SimpleProfiler implements ClassFileTransformer
{
protected String agentArgString = "";
protected Instrumentation instrumentation;
public static void premain(String agentArgs, Instrumentation inst)
{
SimpleProfiler profiler = new SimpleProfiler(agentArgs, inst);
}
public SimpleProfiler(String agentArgs, Instrumentation inst)
{
agentArgString = agentArgs;
instrumentation = inst;
instrumentation.addTransformer(this);
}
public byte[] transform(ClassLoader loader,
String className,
Class<?> classBeingRedefined,
ProtectionDomain protectionDomain,
byte[] classfileBuffer)
throws IllegalClassFormatException
{
System.out.println("SimpleProfiler.transform(): class: " + className + " (" + classfileBuffer.length + " bytes)");
return null;
}
}
This class
- provides the premain method that the runtime needs to launch this profiling agent when the target application launches
- adds itself as a class file transformer using the Instrumentation object passed to it by the runtime
- implements a very simple transform method (returning null means the transformer does not modify the class file)
Premain-Class: com.example.profiler.SimpleProfiler
Now you should be able to build with
mvn clean install
To see our profiler in action, modify the command line of any Java application you have with the following:
-javaagent:<path to your profiler project directory>/target/JavaProfiler-1.0-SNAPSHOT.jar
This option will cause the premain method of the profiler to be called before the target application's classfiles are loaded, and will give the profiler an opportunity to modify their bytecodes as they are loaded.
I ran a simple Java-based JDBC query tool with this agent and my output from the transform method looked like the following:
SimpleProfiler.transform(): class: Query (21580 bytes)
SimpleProfiler.transform(): class: java/sql/SQLException (2836 bytes)
SimpleProfiler.transform(): class: java/awt/Component$2 (854 bytes)
SimpleProfiler.transform(): class: java/awt/Component$4 (777 bytes)
SimpleProfiler.transform(): class: java/sql/ResultSet (8938 bytes)
SimpleProfiler.transform(): class: java/sql/Wrapper (337 bytes)
SimpleProfiler.transform(): class: java/sql/ResultSetMetaData (1045 bytes)
SimpleProfiler.transform(): class: java/awt/AWTEvent$1 (539 bytes)
SimpleProfiler.transform(): class: sun/awt/AWTAccessor$AWTEventAccessor (270 bytes)
SimpleProfiler.transform(): class: sun/reflect/misc/Trampoline (482 bytes)
SimpleProfiler.transform(): class: sun/reflect/GeneratedConstructorAccessor1 (1277 bytes)
SimpleProfiler.transform(): class: sun/reflect/GeneratedMethodAccessor1 (918 bytes)
SimpleProfiler.transform(): class: javax/swing/text/WrappedPlainView (7040 bytes)
SimpleProfiler.transform(): class: javax/swing/text/BoxView (8593 bytes)
SimpleProfiler.transform(): class: javax/swing/text/CompositeView (6079 bytes)
SimpleProfiler.transform(): class: javax/swing/text/WrappedPlainView$WrappedLine (5054 bytes)'
and so on. You are probably thinking it would be nice to restrict the set of classes that are inspected (and possibly instrumented). This is where the agent argument string (passed to premain) comes in handy. This is a single java.lang.String, rather than the usual array as in the main method, but it's a simple matter to parse one. For example, you could pass in a comma-delimited list of regular expressions to determine what classes get inspected and which do not. If we don't do a little filtering, our profiler's performance will suffer and any output we create on the instrumentation process will be overwhelming, so I will provide sample argument-parsing code in the example without spending time discussing it.
I should say at this point that I've seen a number of blog postings on this subject, all of which stop here and say "Next, we'll use an open-source package to insert bytecodes etc.!". I have yet to see a follow-on where this actually occurs. I was thinking of putting this in a follow-on posting, but I got here (Starbucks) by bus, and on the off chance I get run over catching one home, let's go ahead and do something meaningful with the bytecodes before we end this post.
I looked at ASM, BCEL and Javassist, and decided on Javassist (Why? Not too much -- and not too little -- 'getting started' documentation.) Having tried it, it was so easy to use I haven't tried any of the others yet.
As you would expect, Javassist builds a representation of the class file by inspecting the bytecode array. It also includes some very handy methods for inserting blocks of code (which you specify in String form) at the beginning and ending of methods (among many other possibilities, of course). "Insert before" and "insert after" are exactly what I want for this profiler. I want to insert code to print out an "entry" or "exit" message in every method.
A simple way to do this with Javassist is to modify the transform method as below (preceded by some import statements). Note the addition of the regular-expression-processing code:
import java.util.regex.Matcher;
import java.util.regex.Pattern;
import java.util.regex.PatternSyntaxException;
import javassist.CannotCompileException;
import javassist.ClassPool;
import javassist.CtClass;
import javassist.CtConstructor;
import javassist.ByteArrayClassPath;
import javassist.CtMethod;
There is a new attribute for the profiler:
protected Pattern[] classRegexPatterns = null;
which gets initialized at the end of the constructor:
// agentArgString is list of regexes of classes to instrument:
if (agentArgString != null && agentArgString.length() > 0)
{
String[] classRegexes = agentArgString.split(",");
classRegexPatterns = new Pattern[classRegexes.length];
for (int i=0; i<classRegexes.length; i++)
{
classRegexPatterns[i] = Pattern.compile(classRegexes[i]);
}
}
Now, for the new transform method:
public byte[] transform(ClassLoader loader,
String className,
Class<?> classBeingRedefined,
ProtectionDomain protectionDomain,
byte[] classfileBuffer)
throws IllegalClassFormatException
{
for (int i=0; i<classRegexPatterns.length; i++)
{
Matcher matcher = classRegexPatterns[i].matcher(className);
if (matcher.matches())
{
try
{
// first modify the class name for javassist. convert slashes to dots:
String javassistClassName = className.replace('/', '.');
// turn bytecodes into a Javassist CtClass
ClassPool cp = ClassPool.getDefault();
cp.insertClassPath(new ByteArrayClassPath(javassistClassName, classfileBuffer));
CtClass cc = cp.get(javassistClassName);
// add output at the beginning and end of each method
CtMethod[] methods = cc.getMethods();
for (int k=0; k<methods.length; k++)
{
// do not instrument inherited methods:
if (methods[k].getLongName().startsWith(javassistClassName))
{
methods[k].insertBefore("System.out.println(\"Entering " + methods[k].getLongName() + "\");");
methods[k].insertAfter("System.out.println(\"Exiting " + methods[k].getLongName() + "\");");
}
}
// return the new bytecode array:
byte[] newClassfileBuffer = cc.toBytecode();
return newClassfileBuffer;
}
catch (Exception exc)
{
System.err.println(exc.getClass().getName() + ": " + exc.getMessage());
if (!(exc instanceof CannotCompileException))
{
// don't care about the stack trace if there was no method body, etc.:
exc.printStackTrace();
}
}
}
}
return null;
}
Note that the Java runtime returns class names slash-delimited, while Javassist expects them to be dot-delimited. Other than that detail, Javassist has no trouble creating and manipulating class file objects from our byte arrays. Also note that I have chosen not to instrument all methods. The Javassist full method name starts with the Javassist class name. To avoid instrumenting methods in parent classes (which normally results in Javassist's throwing an exception because it does not have access to the method body), I have chosen to restrict instrumentation to the methods defined for the class in question. You can remove the if statement and see what happens...
Note the insertBefore() and insertAfter() methods. These are also available for your target application's constructors (retrieved by CtClass.getConstructors()), but I left constructor instrumentation out of this profiler to keep it as short as possible.
To build the profiler, add the following dependency to your pom.xml file:
<dependency>
<groupId>javassist</groupId>
<artifactId>javassist</artifactId>
<version>3.8.0.GA</version>
</dependency>
and rebuild with
mvn install
Your target application launch will now need to include the Javassist jar file in its classpath. If you have Javassist installed, just point to the jar file there. If not, you can find it in your local Maven repository, as Maven downloaded it to perform the updated build.
Now, relaunch your target application. Note from the package documentation that you pass in your agent argument string at the end of the -javaagent option, following an equals sign. For example, I used:
-javaagent:<path to your profiler project directory>/target/JavaProfiler-1.0-SNAPSHOT.jar=.*Query.*
Note as it runs that you are now seeing console output when methods are entered and exited. In my query-tool example, I see the following:
Entering Query.main(java.lang.String[])
Entering Query.layOutTool()
Exiting Query.layOutTool()
Entering Query.initializeTool()
Entering Query$DatabaseConnection.toString()
Exiting Query$DatabaseConnection.toString()
Entering Query.loadQueries()
Exiting Query.loadQueries()
Exiting Query.initializeTool()
Entering Query.addListeners()
Exiting Query.addListeners()
Entering Query.setInitialDividerLocations()
Exiting Query.setInitialDividerLocations()
Exiting Query.main(java.lang.String[])
Entering Query$DatabaseConnection.toString()
Exiting Query$DatabaseConnection.toString()
Entering Query$DatabaseConnection.toString()
Exiting Query$DatabaseConnection.toString()
Entering Query$DatabaseConnection.toString()
Exiting Query$DatabaseConnection.toString()
and so on.
Following the log output from this profiler isn't that exciting, either! But note what is now available to you. First of all, the profiler is loaded by the same classloader as your target application. This means that if you have methods in your profiler to process method-entry and method-exit events, you can insert bytecodes into the target application to call your profiler (I used a singleton pattern, with a static getInstance() method, etc., in my in-house profiler application). You can insert code to send along the system time stamp, and your profiler can keep a running total of the execution time, number of invocations, percentage of total time, and so on, of the target application. If you do something like this, be sure to include the full method signature in your output, as well as the calling thread's ID, to correctly match your entry and exit events.
Once you are collecting sufficient information, you can start monitoring it for anomalies and generate events (e.g. JMS messages) for incidents you find interesting, and customize your profiler for specific problems and customer situations.
