Java Profiling: Under the Covers

At some point, most developers will get tasked with troubleshooting a performance issue. If at any time you've actually been lucky enough to get paid to worry about performance in general, you probably have a better toolkit (on your desktop and in your head) than the average developer. If, on the other hand, such an assignment is a relatively rare occurrence, you probably will rely on a combination of loggers, debuggers, various open-source profilers (how many companies have you worked at that will spring for a paid license?), and your old friend System.out.println().

This article is geared toward you if you are interested in the instrumentation hooks provided by the Java programming language. I won't be discussing available profilers, either open-source or otherwise; there is a lot of information on the Web about that topic. Here, you'll see how easily and quickly you can write your own profiler. Profilers tend to be rather expensive to run, although most have features (like selective instrumentation, sampling, etc.) that are designed to minimize their run-time impact. But they provide a general functionality, and if you learn how they are built, you can develop a compact profiler that is narrowly targeted to exactly what you need to do.

Overview

The first place you should look is the API docs for java.lang.instrument. This package is quite small, with only a handful of classes, but it is the entry point for our grassroots Java profiler. This package provides you with two key pieces of functionality:

• A mechanism to intercept Java classes (specifically, their bytecode)

• The ability to modify bytecode as it is being loaded

Conceptually, it's that simple. As examples, you could modify some or all classes to make calls to a profiling class on method entry and exit, or you could instrument every block of exception-handling code to generate an event for an event-processing agent.

Another topic touched on in the package instrumentation is the agent launching mechanism. You can launch your profiler either when your target application launches, or afterwards, via an attachment mechanism. As the package documentation notes, starting an agent at JVM startup is fully specified, while starting an agent after the JVM has started is implementation dependent. Java HotSpot implementations support agent start after JVM startup; I'll cover both approaches in this article.

A Minimal Instrumentation Agent

In this section, we'll build a minimal agent. It won't actually instrument any code, but it will provide the structure for doing so. The point is to get the agent launched and to at least note the bytecodes as they are loading.

Two things you must need to know to build this agent are

1. How will you launch it?

2. What is the mechanism for intercepting the classes as they are loaded?

The first question is answered in the java.lang.instrument package documentation. Basically, you:

• Provide one of the two method signatures in your profiler:

  • public static void premain(String agentArgs, Instrumentation inst)

  •  

    public static void premain(String agentArgs)

• Add a line to the manifest file of your profiler's .jar file:

• Premain-Class: fully qualified name of your profiler class

• Launch your target (to-be-profiled) application with the following command-line option:

• -javaagent:jarpath[=options]

Now, let's build an example. Create a new class, com.example.profiler.Profiler, as follows:

package com.example.profiler;

import java.lang.instrument.Instrumentation;

public class Profiler
{
 
public static void premain(String agentArgs, Instrumentation inst)
 {
    System.out.println("premain");
  }

} 

Next, create a manifest.mf file with the following single line:

Premain-Class: com.example.profiler.Profiler

Compile the class and build a .jar file, including the above manifest. You now have an agent. Choose a Java application and insert the following option into its launcher:

-javaagent: path to jar file

and launch the target application from a shell or command prompt. You should see the single line

premain

before any output from your target application. Obviously, this "profiler" does not instrument your target application, but it represents the bare minimum implementation required for a valid instrumentation agent.

Intercepting bytecode

You probably noticed the unused Instrumentation parameter from our premain method above. When the Java runtime hands you an instance of an Instrumentation, you are provided the hook you need to provide your own ClassFileTransformer. ClassFileTransformer is an interface with a single method -- transform. It is in this transform method that you will get the opportunity to intercept the class bytecodes and instrument it or not, as you choose.

Next, we'll save the passed-in Instrumentation instance, create a ClassFileTransformer, and pass it to the Instrumentation instance. Below is an example:

package com.example.profiler;


import java.lang.instrument.ClassFileTransformer;
import java.lang.instrument.IllegalClassFormatException;
import java.lang.instrument.Instrumentation;
import java.security.ProtectionDomain;


public class Profiler implements ClassFileTransformer
{

 protected Instrumentation instrumentation = null;
 
 public static void premain(String agentArgs, Instrumentation inst)
 {
   System.out.println("premain");
   Profiler profiler = new Profiler(inst);
  }
 
 public Profiler(Instrumentation inst)
 {
   instrumentation = inst;
   instrumentation.addTransformer(this);
  }

  public byte[] transform(ClassLoader loader, String className, Class classBeingRedefined,
                                    ProtectionDomain protectionDomain, byte[] classfileBuffer)
                                             throws IllegalClassFormatException
 {
   System.out.println("transform(" + className + ") (" + classfileBuffer.length + " bytes)");
    return null;
  }

} 

Note that at this point we simply print the name and the size of the class passed to our transform method. Also note the Javadocs state that the method should return null if it chooses not to transform the class (returning the original classbyte array works, too). If I launch a simple "Hello, world!" program with this agent, I will see the following output:

premain
transform(HelloWorld) (1173 bytes)
Hello, world!  

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 + "'");
	}
}

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.

Attaching to a Running Application

I mentioned earlier that this functionality, while supported, is implementation dependent. In this section, I'll point you to the information you need to attach to a Sun HotSpot JVM.

If you've used JDK tools like Java VisualVM or JConsole, you've seen the attach API at work. If you're going to attach to a running process, you need to get a handle for it (a VirtualMachineDescriptor, specifically), which implies a method for listing processes (see VirtualMachine.list()). These are the process descriptors you see in the above tools' connect dialogs at launch time. The best place to start is to look at the API documentation for com.sun.tools.attach. This information can be found in the tools documentation of your JDK documentation download, or online. From there, take a look at the documentation for the com.sun.tools.attach.VirtualMachine class -- it provides an outline for getting started. I'll start with this, pointing out some of the issues you can run into along the way.

The basic process is outlined below:

• Create a public static void agentmain() method in your profiling agent (if you have already created a launch-time profiling agent, this can contain the same logic as your premain()method).

• Add an Agent-Class: attribute to your profiler's manifest file, specifying the fully-qualified name of your profiler class.

• In your launch application, perform the following steps:

  1. Obtain a descriptor for the target JVM.

  2. Obtain a VirtualMachine instance with the static VirtualMachine.attach()method.

  3. Load your profiling agent into the target JVM with the VirtualMachine.loadAgent()method.

  4. Detach from the target JVM.

At this point, your profiler's agentmain() method will be called and you are in business.

An example of code that would perform these steps follows:

try
{
VirtualMachine vm = VirtualMachine.attach(pid);
// load agent into target VM
vm.loadAgent(agentPath);
// detach
vm.detach();
}
catch (AgentInitializationException aie)
{
System.err.println("AgentInitializationException: " + aie.getMessage());
aie.printStackTrace();
}
catch (AgentLoadException ale)
{
System.err.println("AgentLoadException: " + ale.getMessage());
ale.printStackTrace();
}
catch (AttachNotSupportedException anse)
{
System.err.println("AttachNotSupportedException: " + anse.getMessage());
anse.printStackTrace();
}
catch (IOException ioe)
{
System.err.println("IOException: " + ioe.getMessage());
ioe.printStackTrace();
}

 
While I don't provide a fully-functional example profiler here that uses the attach API, the above code is taken from the open-source MonkeyWrench profiler (which will be discussed in a future article). For more details on possible issues that can arise while using this API (and solutions!) please see my post "Instrumenting running Java processes with the com.sun.tools.attach API" at http://wayne-adams.blogspot.com/2009/07/instrumenting-running-java-processes.html.

Final Thoughts

Now that you have the basic framework of a profiler, here are some observations and ideas.

As I alluded to earlier, you can get a reference to the ThreadMXBean on your method entry and exit notifications. Since you can get the ID of the current thread, you can query the MXBean and retrieve its ThreadInfo object and other properties. This will give you the thread's accumulated CPU time and the stack trace, among other things. If you want to profile CPU time, you should keep in mind that you'll need the full method or constructor signature (parameters included), class name, and thread ID to uniquely identify the trace of execution in and out of a method. Also, to correctly handle recursive method calls, when you match an exit notification with an entry notification, you'll have to unroll the pending method entry notifications by most-recent-entry first, in order to match the correct entry with the exit.

The stack trace information is useful because it allows you to build profiles of the paths used to reach the method or constructor you're profiling. These profiles are called "sites" in hprof, the very useful but rather expensive profiling agent provided with the JDK. Your profiler can maintain a list of unique stack traces for each method invocation and provide a summary of the sites and their relative frequency as execution progresses.

If you're profiling constructor activity and are interested in the sizes of objects being instantiated, the Instrumentation class has a getObjectSize() method. The API docs say that this size is implementation-dependent and an approximation. The size appears to be a shallow-copy object size.

This concludes our survey of the instrumentation API provided by the JDK. While a compact package, java.lang.instrument, in conjunction with a good bytecode-injection library, provides everything you need to get started writing a profiler of your own. Even if you don't find yourself in the position of needing to write a profiler, knowing a little about how to do so will no doubt make you appreciate Java VisualVM or hprof -- or your licensed commercial profiler -- a little more than you did before!