Profiling is a technique for measuring where software programs consume resources, including CPU time and memory. In this article, software architect Andrew Wilcox explains the benefits of profiling and some current profiling options and their shortcomings. He then shows you how to use the new Java™ 5 agent interface and simple aspect-oriented programming techniques to build your own profiler.
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.
Limitations of profilers
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.
The ideal profiler
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.
Build it yourself!
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.
Creating an agent
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:
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.ClassFileTransformer interface:
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
A simple agent
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
A profiling aspect
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");
}
Using the ASM plugin
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.)
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.
Loading the ASM classes
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
Running the profiler
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
org/apache/tools/ant/Project$AntRefTable
org/apache/tools/ant/Project$AntRefTable
org/apache/tools/ant/types/FilterSet
org/apache/tools/ant/types/DataType
org/apache/tools/ant/ProjectComponent
org/apache/tools/ant/ProjectComponent
org/apache/tools/ant/types/DataType
org/apache/tools/ant/types/FilterSet
org/apache/tools/ant/ProjectComponent setProject start 1138565072055
org/apache/tools/ant/ProjectComponent setProject end 1138565072055
org/apache/tools/ant/types/FilterSetCollection
org/apache/tools/ant/types/FilterSetCollection addFilterSet start 1138565072057
org/apache/tools/ant/types/FilterSetCollection addFilterSet end 1138565072057
org/apache/tools/ant/types/FilterSetCollection
org/apache/tools/ant/util/FileUtils
org/apache/tools/ant/util/FileUtils
org/apache/tools/ant/util/FileUtils newFileUtils start 1138565072076
org/apache/tools/ant/util/FileUtils
org/apache/tools/ant/taskdefs/condition/Os
org/apache/tools/ant/taskdefs/condition/Os
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
org/apache/tools/ant/util/FileUtils newFileUtils end 1138565072082
org/apache/tools/ant/input/DefaultInputHandler
org/apache/tools/ant/input/DefaultInputHandler
org/apache/tools/ant/Project
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
org/apache/tools/ant/util/StringUtils
org/apache/tools/ant/util/StringUtils
Tracking the call stack
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.
Modifying the Profile class
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:
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.
In conclusion
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.
(http://www-128.ibm.com/developerworks/java/library/j-jip/index.html?ca=drs-#download)
No comments:
Post a Comment