Build your own profiling tool
Create an ideal profiler using the Java 5 agent interface and AOP
Level: Introductory
Andrew Wilcox ([email protected]), Senior Architect, MentorGen LLC
14 Mar 2006
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.
 |
|
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:
|
If the agent was packaged in a JAR file called vc.jar, the JVM would be started with the -javaagent option, as follows:
|
|
|
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
|
If you were profiling by hand, your next step would be to modify every method to look something like this:
|
|
|
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
|
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
|
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
|
|
|
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
|
|
|
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 | |
 |
Get Adobe® Reader® |
|
|
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. - "Eye on performance: Profiling on the edge (Jack Shirazi and Kirk Pepperdine, developerWorks, September 2004): A day in the life of two Java developers and their many profiling tools.
- 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.
- ASM bytecode manipulation framework: Can be used to dynamically generate stub classes or other proxy classes directly in binary form, or to dynamically modify classes at load time.
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. |
