![Close [x]](http://dw1.s81c.com/i/c.gif){kind=small}
Whether you're using System.out.println()
or a profiling tool such as hprof or
OptimizeIt, code profiling should be an essential component of your
software development practice. This article discusses
the most common approaches to code profiling and explains their
downsides. It provides a list of best-of-breed features you might
look for in an ideal profiler and explains why aspect-oriented
techniques are well suited to achieving some of those features. It
also introduces you to the JDK 5.0 agent interface and walks you through
the steps of using it to build your own aspect-oriented profiler.
Note that the example profiler and complete source code for this article are based on the Java Interactive Profiler (JIP) -- an open-source profiler built using aspect-oriented techniques and the Java 5 agent interface. See Resources to learn more about JIP and other tools discussed in this article.
Profiling tools and techniques
Most Java developers start out measuring application performance
using System.currentTimeMillis() and
System.out.println(). System.currentTimeMillis() is easy to use: you just measure the time at the beginning of a method and again at the end,
and print the difference, but it has two big downsides:
- It's a manual process, requiring you to determine what code to
measure; instrument the code; recompile, redeploy, run, and analyze the
results; back out the instrumentation code when done; and go through all
the same steps again the next time there's a problem.
- It doesn't give a comprehensive view of how all the parts of the application are performing.
To get around these issues, some developers turn to code profilers
like hprof, JProbe, or OptimizeIt. Profilers
avoid the problems associated with ad-hoc measurement because you don't
have to modify your program to use them. They also give you a
more comprehensive view of program performance because they gather
timing information for every method call, not just a particular section
of the code. Unfortunately, profiling tools also have some downsides.
Profilers offer a nice alternative to manual solutions like System.currentTimeMillis(), but they're far from
ideal. For one thing, running a program with hprof
can slow it down by a factor of 20. That means an ETL (extract,
transform, and load) operation that normally takes an hour could take a
full day to profile! Not only is waiting inconvenient, but changing the
timescale of the application can actually skew the results. Take a
program that does a lot of I/O. Because the I/O is performed by the
operating system, the profiler doesn't slow it down, so your I/O could
appear to run 20 times faster than it actually does! As a result, you
can't always count on hprof to give you an
accurate picture of your application's performance.
Another problem with hprof has to do with
how Java programs are loaded and run. Unlike programs in statically
linked languages like C or C++, a Java program is linked at run time
rather than compile time. Classes aren't loaded by the JVM until the
first time they're referenced, and code isn't compiled from bytecode
to machine code until it has been executed a number of times. If you're
trying to measure the performance of a method but its class hasn't yet
been loaded, your measurement will include the class loading time and
compilation time in addition to the run time. Because these things happen only at
the beginning of an application's life, you usually don't want to
include them when measuring the performance of long-lived applications.
Things can get even more complicated when your code is running in an
application server or servlet engine. Profilers like hprof profile the entire application, servlet
container and all. The trouble is, you usually don't want to profile the
servlet engine, you just want to profile your application.
Like selecting any other tool, selecting a profiler involves
trade-offs. Free tools like hprof are easy to
use, but they have limitations, such as the inability to filter out classes or
packages from the profile. Commercial tools offer more features but can
be expensive and have restrictive licensing terms. Some profilers require
that you launch the application through the profiler, which means
reconstructing your execution environment in terms of an unfamiliar
tool. Picking a profiler involves compromises, so what should an
ideal profiler look like? Here's a short list of the features you might
look for:
- Speed: Profiling can be painfully slow. But you can speed things up by using a profiler that doesn't automatically profile every class.
- Interactivity: The more interaction your profiler allows, the
more you can fine-tune the information you get from it. For example,
being able to turn the profiler on and off at run time helps you avoid
measuring class loading, compilation, and interpreted execution
(pre-JIT) times.
- Filtering: Filtering by class or package lets you focus on
the problem at hand, rather than being overwhelmed by too much
information.
- 100% Pure Java code: Most profilers require native libraries, which limits the number of platforms that you can use them on. An ideal profiler wouldn't require the use of native libraries.
- Open source: Open source tools typically let you get up and running quickly, while avoiding the restrictions of commercial licenses.
The problem with using System.currentTimeMillis() to generate timing
information is that it's a manual process. If you could automate the
instrumentation of the code, many of its disadvantages would go away.
This type of problem is a perfect candidate for an aspect-oriented
solution. The agent interface introduced in Java 5 is ideal for
building an aspect-oriented profiler because it gives you an easy way to hook
into the classloader and modify classes as they're loaded.
The remainder of the article focuses on the BYOP (build your own profiler). I'll introduce the agent interface and show you how to create a simple agent. You'll learn the code for a basic profiling aspect, as well as the steps you can take to modify it for more advanced profiling.
The -javaagent JVM option is,
unfortunately, very sparsely documented. You won't find many books on
the topic (no Java Agents for Dummies or Java Agents in 21
days), but you will find some good sources
in the Resources section, along with the overview here.
The basic idea behind agents is that, as the JVM loads a class, the agent can modify the class's bytecode. You can create an agent in three steps:
- Implement the
java.lang.instrument.ClassFileTransformerinterface:
public interface ClassFileTransformer { public byte[] transform(ClassLoader loader, String className, Class<?> classBeingRedefined, ProtectionDomain protectionDomain, byte[] classfileBuffer) throws IllegalClassFormatException; }
- Create a "premain" method. This method is called before the application's
main()method and looks like this:
package sample.verboseclass; public class Main { public static void premain(String args, Instrumentation inst) { ... } }
- In the agent JAR file, include a manifest entry identifying the class containing the
premain()method:
Manifest-Version: 1.0 Premain-Class: sample.verboseclass.Main
Your first step toward building a profiler is to create a simple agent that prints out the name of each class as
it's loaded, similar to the behavior of the -verbose:class JVM option. As you can see in
Listing 1, this requires only a few lines of code:
Listing 1. A simple agent
package sample.verboseclass;
public class Main {
public static void premain(String args, Instrumentation inst) {
inst.addTransformer(new Transformer());
}
}
class Transformer implements ClassFileTransformer {
public byte[] transform(ClassLoader l, String className, Class<?> c,
ProtectionDomain pd, byte[] b) throws IllegalClassFormatException {
System.out.print("Loading class: ");
System.out.println(className);
return b;
}
}
|
If the agent was packaged in a JAR file called vc.jar, the JVM would be started with the -javaagent option, as follows:
java -javaagent:vc.jar MyApplicationClass |
With the basic elements of an agent in place, your next step is to add a simple profiling aspect to your application classes as they're loaded. Fortunately, you don't need to master the details of the JVM instruction set to modify bytecode. Instead, you can use a toolkit like the ASM library (from the ObjectWeb consortium; see Resources) to handle the details of the class file format. ASM is a Java bytecode manipulation framework that uses the Visitor pattern to enable you to transform class files, in much the same way that SAX events can be used to traverse and transform an XML document.
Listing 2 is a profiling aspect that can be used to output the class name, method
name, and a timestamp every time the JVM enters or leaves a method. (For a more
sophisticated profiler, you would probably want to use a high-resolution
timer like Java 5's System.nanoTime().)
Listing 2. A simple profiling aspect
package sample.profiler;
public class Profile {
public static void start(String className, String methodName) {
System.out.println(new StringBuilder(className)
.append('\t')
.append(methodName)
.append("\tstart\t")
.append(System.currentTimeMillis()));
}
public static void end(String className, String methodName) {
System.out.println(new StringBuilder(className)
.append('\t')
.append(methodName)
.append("\end\t")
.append(System.currentTimeMillis()));
}
}
|
If you were profiling by hand, your next step would be to modify every method to look something like this:
void myMethod() {
Profile.start("MyClass", "myMethod");
...
Profile.end("MyClass", "myMethod");
}
|
Now you need to figure out what the bytecode for the Profile.start() and Profile.end() calls
looks like -- which is where the ASM library comes in. ASM has a
Bytecode Outline plugin for Eclipse (see Resources) that allows you to view the bytecode of
any class or method. Figure 1 shows the bytecode for the method above. (You could also use a dis-assembler like
javap, which is part of the JDK.)
Figure 1. Viewing bytecode using the ASM plugin
The ASM plugin even produces the ASM code that can be used to generate the corresponding bytecode, as shown in Figure 2:
Figure 2. The ASM plugin generates code
You can cut and paste the highlighted code shown in Figure 2 into your agent to call a generalized version of the Profile.start() method, as shown in Listing 3:
Listing 3. The ASM code to inject a call to the profiler
visitLdcInsn(className); visitLdcInsn(methodName); visitMethodInsn(INVOKESTATIC, "sample/profiler/Profile", "start", "(Ljava/lang/String;Ljava/lang/String;)V"); |
To inject the start and end calls, subclass ASM's MethodAdapter, as shown in Listing 4:
Listing 4. The ASM code to inject a call to the profiler
package sample.profiler;
import org.objectweb.asm.MethodAdapter;
import org.objectweb.asm.MethodVisitor;
import org.objectweb.asm.Opcodes;
import static org.objectweb.asm.Opcodes.INVOKESTATIC;
public class PerfMethodAdapter extends MethodAdapter {
private String className, methodName;
public PerfMethodAdapter(MethodVisitor visitor, String className,
String methodName) {
super(visitor);
className = className;
methodName = methodName;
}
public void visitCode() {
this.visitLdcInsn(className);
this.visitLdcInsn(methodName);
this.visitMethodInsn(INVOKESTATIC,
"sample/profiler/Profile",
"start",
"(Ljava/lang/String;Ljava/lang/String;)V");
super.visitCode();
}
public void visitInsn(int inst) {
switch (inst) {
case Opcodes.ARETURN:
case Opcodes.DRETURN:
case Opcodes.FRETURN:
case Opcodes.IRETURN:
case Opcodes.LRETURN:
case Opcodes.RETURN:
case Opcodes.ATHROW:
this.visitLdcInsn(className);
this.visitLdcInsn(methodName);
this.visitMethodInsn(INVOKESTATIC,
"sample/profiler/Profile",
"end",
"(Ljava/lang/String;Ljava/lang/String;)V");
break;
default:
break;
}
super.visitInsn(inst);
}
}
|
The code to hook this into your agent is very simple and is part of the source download for this article.
Because your agent uses ASM, you need to ensure that the ASM classes are loaded for everything to work. There are many class paths in a Java application: the application classpath, the extensions classpath, and the bootstrap classpath. Surprisingly, the ASM JAR doesn't go in any of these; instead, you'll use the manifest to tell the JVM which JAR files the agent needs, as shown in Listing 5. In this case, the JAR files must be in the same directory as the agent's JAR.
Listing 5. The manifest file for the profiler
Manifest-Version: 1.0 Premain-Class: sample.profiler.Main Boot-Class-Path: asm-2.0.jar asm-attrs-2.0.jar asm-commons-2.0.jar |
Once everything is compiled and packaged, you can run your profiler against any Java application. Listing 6 is part of the output from a profile of Ant running the build.xml that compiles the agent:
Listing 6. A sample of the output from the profiler
org/apache/tools/ant/Main runBuild start 1138565072002 org/apache/tools/ant/Project <init> start 1138565072029 org/apache/tools/ant/Project$AntRefTable <init> start 1138565072031 org/apache/tools/ant/Project$AntRefTable <init> end 1138565072033 org/apache/tools/ant/types/FilterSet <init> start 1138565072054 org/apache/tools/ant/types/DataType <init> start 1138565072055 org/apache/tools/ant/ProjectComponent <init> start 1138565072055 org/apache/tools/ant/ProjectComponent <init> end 1138565072055 org/apache/tools/ant/types/DataType <init> end 1138565072055 org/apache/tools/ant/types/FilterSet <init> end 1138565072055 org/apache/tools/ant/ProjectComponent setProject start 1138565072055 org/apache/tools/ant/ProjectComponent setProject end 1138565072055 org/apache/tools/ant/types/FilterSetCollection <init> start 1138565072057 org/apache/tools/ant/types/FilterSetCollection addFilterSet start 1138565072057 org/apache/tools/ant/types/FilterSetCollection addFilterSet end 1138565072057 org/apache/tools/ant/types/FilterSetCollection <init> end 1138565072057 org/apache/tools/ant/util/FileUtils <clinit> start 1138565072075 org/apache/tools/ant/util/FileUtils <clinit> end 1138565072076 org/apache/tools/ant/util/FileUtils newFileUtils start 1138565072076 org/apache/tools/ant/util/FileUtils <init> start 1138565072076 org/apache/tools/ant/taskdefs/condition/Os <clinit> start 1138565072080 org/apache/tools/ant/taskdefs/condition/Os <clinit> end 1138565072081 org/apache/tools/ant/taskdefs/condition/Os isFamily start 1138565072082 org/apache/tools/ant/taskdefs/condition/Os isOs start 1138565072082 org/apache/tools/ant/taskdefs/condition/Os isOs end 1138565072082 org/apache/tools/ant/taskdefs/condition/Os isFamily end 1138565072082 org/apache/tools/ant/util/FileUtils <init> end 1138565072082 org/apache/tools/ant/util/FileUtils newFileUtils end 1138565072082 org/apache/tools/ant/input/DefaultInputHandler <init> start 1138565072084 org/apache/tools/ant/input/DefaultInputHandler <init> end 1138565072085 org/apache/tools/ant/Project <init> end 1138565072085 org/apache/tools/ant/Project setCoreLoader start 1138565072085 org/apache/tools/ant/Project setCoreLoader end 1138565072085 org/apache/tools/ant/Main addBuildListener start 1138565072085 org/apache/tools/ant/Main createLogger start 1138565072085 org/apache/tools/ant/DefaultLogger <clinit> start 1138565072092 org/apache/tools/ant/util/StringUtils <clinit> start 1138565072096 org/apache/tools/ant/util/StringUtils <clinit> end 1138565072096 |
So far you've seen how to build a simple aspect-oriented profiler with just a few lines of code. While a good start, the example profiler doesn't gather thread and call stack data. Call stack information is necessary to determine the gross and net method execution times. In addition, each call stack is associated with a thread, so if you want to track call stack data, you'll need thread information as well. Most profilers use a two-pass design for this kind of analysis: first gather data, then analyze it. I'll show you how to adopt this approach rather than just printing out the data as it is gathered.
You can easily enhance your Profile class
to capture call stack and thread information. For starters, instead of printing out times at the start and end of each method, you can store the information using the data structures shown in Figure 3:
Figure 3. Data structures for tracking call stack and thread information
There are a number of ways to gather information about the call
stack. One is to instantiate an Exception,
but doing this at the beginning and end of each method would be far too
slow. A simpler way is for the profiler to manage its own internal call
stack. This is easy because start() is called
for every method; the only tricky part is unwinding the internal call
stack when an exception is thrown. You can detect when an exception has
been thrown by checking the expected class and method name when Profile.end() is called.
Printing is similarly easy to set up. You can create a
shutdown hook using Runtime.addShutdownHook() to register a
Thread that runs at shutdown time and prints a profiling
report to the console.
This article introduced you to the current tools and technologies most commonly used for profiling and discussed some of their limitations. You now have a list of features you might expect from an ideal profiler. Finally, you learned how to use aspect-oriented programming and the Java 5 agent interface to build your own profiler incorporating some of these ideal features.
The example code in this article is based on the Java Interactive Profiler, an open-source profiler built using the techniques I've discussed here. In addition to the basic features found in the example profiler, JIP incorporates the following:
- Interactive profiling
- The ability to exclude classes or packages
- The ability to include only classes loaded by a particular classloader
- A facility for tracking object allocations
- Performance measurement in addition to code profiling
JIP is distributed under a BSD-style license. See Resources for download information.
| Description | Name | Size | Download method |
|---|---|---|---|
| Source code for the simple profiler developed here | j-jipsimple-profiler-src.zip | 51KB | HTTP |
| Source code for the verbose-class example | j-jipverbose-class-src.zip | 2KB | HTTP |
Information about download methods
Learn
-
java.lang.instrument: The Javadoc for the agent interface. -
Instrumentation: Modify Applications with Java 5 Class File Transformations (R. J. Lorimer, JavaLobby, June 2005): One of the few sources of information about the Java 5 agent interface.
-
"AOP@Work: Performance monitoring with AspectJ, Part 1" and Part 2 (Ron Bodkin, developerWorks, September/November 2005): Ron Bodkin uses the open source project Glassbox Inspector to demonstrate that AOP is a natural fit for solving the problems of system monitoring.
- "Using HPROF to Tune Performance" (JDC Tech Tips, January 24, 2000 ): Gets you started with
hprofand provides a code example showing improved performance. -
Classworking toolkit: Dennis Sosnoski explores ASM in his regular series on developerWorks.
- The Java technology zone: Hundreds of articles about every aspect of Java programming.
Get products and technologies
- Java Interactive Profiler: The author's high-performance, low-overhead profiler that is written entirely in Java code.
- ASM Bytecode Outline plugin for Eclipse: Shows dis-assembled bytecode of current Java editor or class file, allows bytecode comparison for Java/class files, and shows ASMifier code for current bytecode.
Discuss
- JVM and Bytecode discussion forum: This new forum, hosted by Dennis Sosnoski, covers issues related to Java bytecode, the Java binary class format, and general JVM issues.
- developerWorks Forums: Get involved in the developerWorks community.
Andrew Wilcox is a software architect at MentorGen LLC in Columbus, Ohio. He has over 15 years of industry experience, nine of them using the Java platform. Andrew specializes in frameworks, performance tuning, and metaprogramming. His focus is on tools and techniques to increase developer productivity and software reliability. He is also the creator of the Java Interactive Profiler.
