I'm a software architect/consultant in Boulder, Colorado. I started blogging at: http://wayne-adams.blogspot.com/, but have since started the new blog, Data Sceintist in Training which will cover the areas I am learning as part of my own "big data" training, including the Hadoop family, frameworks like OpenStack, the R programming language, column-oriented databases and the art of examining data sets for useful patterns. The original blog will be kept alive with Java-specific posts. Wayne is a DZone MVB and is not an employee of DZone and has posted 35 posts at DZone. You can read more from them at their website. View Full User Profile

Java Profiling: Under the Covers

12.01.2009
| 28922 views |
  • submit to reddit

Now, the Hard Part

To actually instrument code, I recommend you use a bytecode-injection library. For this example, I use Javassist . Javassist will create a Java class representation from the bytecode array, and from there it is very easy to obtain representations of the constructors, using CtClass.getConstructors(), and the methods, using CtClass.getMethods(). The CtConstructor and CtMethod insertBefore() andinsertAfter() methods provide a very simple way to instrument your code.

The simple profiler, minimally modified to insert output at the beginning and end of method calls, follows:

 

package com.example.profiler;

import java.lang.instrument.ClassFileTransformer;
import java.lang.instrument.IllegalClassFormatException;
import java.lang.instrument.Instrumentation;
import java.io.IOException;
import java.security.ProtectionDomain;
import javassist.CannotCompileException;
import javassist.ClassPool;
import javassist.CtClass;
import javassist.ByteArrayClassPath;
import javassist.CtMethod;
import javassist.NotFoundException;

public class Profiler implements ClassFileTransformer
{

protected Instrumentation instrumentation = null;
protected ClassPool classPool;

public static void premain(String agentArgs, Instrumentation inst)
{
Profiler profiler = new Profiler(inst);
}

public Profiler(Instrumentation inst)
{
instrumentation = inst;
classPool = ClassPool.getDefault();
instrumentation.addTransformer(this);
}

public byte[] transform(ClassLoader loader, String className, Class classBeingRedefined,
ProtectionDomain protectionDomain, byte[] classfileBuffer)
throws IllegalClassFormatException
{
try
{
classPool.insertClassPath(new ByteArrayClassPath(className, classfileBuffer));
CtClass cc = classPool.get(className);
CtMethod[] methods = cc.getMethods();
for (int k=0; k<methods.length; k++)
{
if (methods[k].getLongName().startsWith(className))
{
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 (IOException ioe)
{
System.err.println(ioe.getMessage() + " transforming class " + className + "; returning uninstrumented class");
}
catch (NotFoundException nfe)
{
System.err.println(nfe.getMessage() + " transforming class " + className + "; returning uninstrumented class");
}
catch (CannotCompileException cce)
{
System.err.println(cce.getMessage() + " transforming class " + className + "; returning uninstrumented class");
}
return null;
}

}


The check for the class name is a workaround for a common issue -- a "no method body" CannotCompileException thrown by Javassist when the method is an inherited method. We'll explicitly display those exceptions in the next example of the profiler.

Running my "Hello, world!" application with this profiler (don't forget to include the Javassist jar file in the classpath) gives the following output (note: I've over-engineered my target application so that there will be a little more profiler output):

Entering HelloWorld.main(java.lang.String[])
Entering HelloWorld.setName(java.lang.String)
Exiting HelloWorld.setName(java.lang.String)
Entering HelloWorld.emitGreeting()
Hello, world!
Exiting HelloWorld.emitGreeting()
Exiting HelloWorld.main(java.lang.String[])

Keep in mind that since the profiler is loaded by the system class loader in the same JVM as the target, you could just as easily have instrumented the target code to call methods in your own profiler. For example, you could give your profiler a getInstance() method and inject code to notify your profiler when a method is entered or exited:


package com.example.profiler;
import java.lang.instrument.ClassFileTransformer;
import java.lang.instrument.IllegalClassFormatException;
import java.lang.instrument.Instrumentation;
import java.io.IOException;
import java.security.ProtectionDomain;
import javassist.CannotCompileException;
import javassist.ClassPool;
import javassist.CtClass;
import javassist.ByteArrayClassPath;
import javassist.CtMethod;
import javassist.NotFoundException;
public class Profiler implements ClassFileTransformer
{
protected static Profiler profilerInstance = null;
protected Instrumentation instrumentation = null;
protected ClassPool classPool;
public static void premain(String agentArgs, Instrumentation inst)
{
Profiler profiler = new Profiler(inst);
}
public static Profiler getInstance()
{
return profilerInstance;
}
public Profiler(Instrumentation inst)
{
profilerInstance = this;
instrumentation = inst;
classPool = ClassPool.getDefault();
instrumentation.addTransformer(this);
}
public byte[] transform(ClassLoader loader, String className, Class classBeingRedefined,
ProtectionDomain protectionDomain, byte[] classfileBuffer)
throws IllegalClassFormatException
{
classPool.insertClassPath(new ByteArrayClassPath(className, classfileBuffer));
CtClass cc = null;
try
{
cc = classPool.get(className);
}
catch (NotFoundException nfe)
{
System.err.println("NotFoundException: " + nfe.getMessage() + "; transforming class " + className + "; returning uninstrumented class");
}
CtMethod[] methods = cc.getMethods();
for (int k=0; k<methods.length; k++)
{
try
{
methods[k].insertBefore("com.example.profiler.Profiler.getInstance().notifyMethodEntry(\"" + className + "\", \"" + methods[k].getName() + "\");");
methods[k].insertAfter("com.example.profiler.Profiler.getInstance().notifyMethodExit(\"" + className + "\", \"" + methods[k].getName() + "\");");
}
catch (CannotCompileException cce)
{
System.err.println("CannotCompileException: " + cce.getMessage() + "; instrumenting method " + methods[k].getLongName() + "; method will not be instrumented");
}
}
// return the new bytecode array:
byte[] newClassfileBuffer = null;
try
{
newClassfileBuffer = cc.toBytecode();
}
catch (IOException ioe)
{
System.err.println("IOException: " + ioe.getMessage() + "; transforming class " + className + "; returning uninstrumented class");
return null;
}
catch (CannotCompileException cce)
{
System.err.println("CannotCompileException: " + cce.getMessage() + "; transforming class " + className + "; returning uninstrumented class");
return null;
}
return newClassfileBuffer;
}
public void notifyMethodEntry(String className, String methodName)
{
System.out.println("Thread '" + Thread.currentThread().getName() + "' entering method '" + methodName + "' of class '" + className + "'");
}
public void notifyMethodExit(String className, String methodName)
{
System.out.println("Thread '" + Thread.currentThread().getName() + "' exiting method '" + methodName + "' of class '" + className + "'");
}
}

In this iteration, I've broken out the try-catch clause into several clauses so that we can recover gracefully from a failure to instrument an individual method. The code inserted at the beginning and end of each method now uses a static getInstance() method to retrieve the profiler instance and call notifyxxx() methods on it.

Running this profiler against my over-engineered "Hello, world!" application results in the following output:

CannotCompileException: no method body; instrumenting method java.lang.Object.wait(long); method will not be instrumented
CannotCompileException: no method body; instrumenting method java.lang.Object.notifyAll(); method will not be instrumented
CannotCompileException: no method body; instrumenting method java.lang.Object.getClass(); method will not be instrumented
CannotCompileException: no method body; instrumenting method java.lang.Object.clone(); method will not be instrumented
CannotCompileException: no method body; instrumenting method java.lang.Object.hashCode(); method will not be instrumented
CannotCompileException: no method body; instrumenting method java.lang.Object.notify(); method will not be instrumented
Thread 'main' entering method 'main' of class 'HelloWorld'
Thread 'main' entering method 'setName' of class 'HelloWorld'
Thread 'main' exiting method 'setName' of class 'HelloWorld'
Thread 'main' entering method 'emitGreeting' of class 'HelloWorld'
Hello, world!
Thread 'main' exiting method 'emitGreeting' of class 'HelloWorld'
Thread 'main' exiting method 'main' of class 'HelloWorld'

Note that the methods for which there is no body are methods inherited by the class. For this reason, I typically include a check in the loop over the method names so that I only instrument methods defined in the class I'm instrumenting.

That's it! If you were to add additional information to the notify call (e.g., get the ThreadMXBean and retrieve the current value of the thread's CPU time), you can see how you might be on the road to creating a functional profiler. Even better, you can target it very specifically to provide only the information you want, at only the touchpoints you want, with a flexibility that would be very difficult to achieve with a “black box” profiler.

 

Published at DZone with permission of Wayne Adams, author and DZone MVB.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Comments

Eric Meallier replied on Tue, 2009/12/08 - 6:13am

hard to get this working !

 

during the instrumentation, a RuntimeException was throwed by getMethods() call. The problem comes from the naming convention of the classes.

The classname given by transform is like this test/Test. The classpool understand this syntax but store test.Test. When you are looking for the class (getClass() just before getMethods) the class is lazy loaded (the byte code is not introscepted) but is not good. the problem only appear when the getMethods is called.

A workaround is to call classPool.get(className.replace('/', '.'));

 

Thanks for the article.

Victor Tsoukanov replied on Fri, 2010/02/19 - 1:14am

If you do not want to pay money for profiling tool, there is a free and quite suitable profiler – Netbeans profiler

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.