Java Interactive Profiler

What is JIP?

JIP is a code profiling tool much like the hprof tool that ships with the JDK. There are, however, a few differences:
  1. Interactivity. hprof is not an interactive profiler. It starts when your program starts and ends when the JVM exits. In many cases this doesn't give you a true measure of performance since the Just In Time compiler doesn't compile code on the first pass. In addition, this type of profiler is not useable at all in web applications since you end up profiling the web container as well as the web application. JIP, on the other hand, allows you to turn the profiler on and off while the JVM is running.
  2. No native code. Most profilers have some native component. This is because most profilers use the JVMPI (Java Virtual Machine Profiling Interface) which requires the use of native components. JIP, however, is pure Java. It takes advantage of the Java5™ feature which allows you to hook the classloader. JIP adds aspects to every method of every class that you want to profile. These aspects allow it to capture performance data.
  3. Very low overhead. Most profilers are very slow. In many cases hprof will cause a program to run 20 times slower. JIP, on the other hand, is lightweight. A VM with profiling turned on is about twice as slow as one without a profiler. When the profiler is turned off, there is almost no overhead associated with using JIP.
  4. Performance Timings. JIP gathers performance data. You cannot use most profilers to do timings of your application. hprof, for example, will show you the relative amount of time that is spent in different parts of your code, but hprof has so much overhead, that you cannot use it to get real world timing measurements. JIP, on the other hand, actually tracks the amount of time used to gather performance data and factors that time out of its analysis. This allows you to get close to real world timings for every class in your code. So there is no need to litter your code with System.currentTimeMillis()!
  5. Filters by package/class name. One of the annoying things about hprof is that there is no way to filter out classes by class or package name. JIP allows you to do just that (for more information, look at the profile.properties file). This in not to say that the execution time is not included. It is included but can only be seen in the execution time of the calling routine.

How to use JIP


Note: JIP requires a Java5™ VM.

To run the profiler, you need the following:

These files are loaded by the application classloader and should not be in the extentions loader path. The jar files need to be in the same directory. The properties file can be anywhere.

To use the profiler, you need to use the following JVM arguments:


-javaagent:[DIR]\profile.jar -Dprofile.properties=[DIR2]\profile.properties
			
where [DIR] is the directory that contains the profile.jar
Note: Due to a bug in the JDK on OS X, [DIR] must be a fully qualifed path.
and [DIR2] is the directory that contains the profile.properties

By default (if you don't give a -Dprofile.properties), profiling starts out turned on and the remote interface (use to profile interactively) is turned off (see the profile.properies for more information). In this case JIP works just like hprof, although it is much faster.

When using with stock Tomcat, set the java agent by using the env. variable JAVA_OPTS. For example, on Windows™ use the following:

SET JAVA_OPTS=-javaagent:[DIR]\profile.jar -Dprofile.properties=[DIR2]\profile.properties
Where [DIR1] and [DIR2] are described as above.

Interactive profiling

In some cases, like webapps, you probably want to start out with the profiler turned off. When you get to some case you want to test, you'd like to turn it on, run the test case, turn the profiler off and dump the results. To do these things, you first of all need to change the profile properties file:


profiler=off
remote=on
port=15599
			
To interact with the profiler you need the client.jar which is in the /client directory of the JIP distribution. In my personal experience with webapps, you should exercise a test case at least six times before trying to measure performance. Presumably this is because the Just In Time compiler will observe how the code is used a number of times before compiling it into native code.

Examples

There are some examples of how to use JIP: example.bat, example-ant-1.5.sh and example.sh. All use the example of compiling JIP with ant. example.bat and example-ant-1.5.sh work only with ant 1.5 and example.sh works only with ant 1.6 (this is because the way that ant gets invoked changed between the two releases).

FAQ

Most profilers use native code. How does JIP work if it's written entirely in Java.

Most profilers have some native component. This is because most profilers use the JVMPI (Java Virtual Machine Profiling Interface) which requires the use of native components. JIP, however, is pure Java. It takes advantage of the Java5™ feature which allows you to hook the classloader. JIP adds aspects to every method of every class that you want to profile. These aspects allow it to capture performance data.

Wow, JIP is pretty fast. How can it be faster that other profilers?

JIP's speed is mainly due to the fact that it doesn't profile every class. JIP doesn't profile classes that are in the bootstrap classpath (all of the core Java classes) or classes that are in the extension classpath (i.e., files in -Djava.ext.dirs=). These are classes that you can't change, so it's not every useful to know what their performace is like. It's usually enough to know that a method that is calling one of these classes is slow. You can usually figure out how to optimize things from there.

Where can I get more information about the mechanism that JIP uses?

This IBM DeveloperWorks article gives an overview of the mechanisms that JIP uses.

Am I supposed to put profile.jar in my classpath, my extensions classpath, my bootstrap classpath, or someother classpath?

It is best not to put profile.jar in any of these places. The classes in this JAR are loaded by the application classloader (the classloader that loads classes that are in the classpath), but they don't needed to be in the classpath itself.

JIP's output is missing all of the classes that are part of the JDK, what gives?

JIP doesn't profile classes that are loaded by the bootstrap or extensions classloaders. This is one of the reasons that it is so fast. On a technical level, the classes in JIP are loaded by the javaagent which uses the application classloader. This means that while JIP is capable of instrumenting classes loaded by all classloaders, the instrumentation itself is composed of calls to classes in the JIP package, which are loaded by the application classloader, which aren't visible to classes loaded by the bootstrap and extensions classloaders. For more on this look here.

How can I control which classes and packages JIP profiles?

There are two mechanisms to control which classes and packages JIP profiles. The main one is by using ClassLoaderFilters. A ClassLoaderFilter tells JIP to profile classes based on which classloader was used to load them. Why is this necessary? To start with, JIP cannot profile classes loaded by the Bootstrap or Extensions classloaders. Also, which classloader your application uses can vary by environment. For example, standalone applications use the Application classloader. You can see which class this is by calling ClassLoader.getSystemClassLoader() (usually sun.misc.Launcher$AppClasLoader ). But if you're running in a container like Tomcat or JBoss, the application classloder is used to load the container's classes. The container will use another classloader to load application classes. Since you usually don't want to see all of what is going on inside Tomcat or JBoss, you can use a ClassLoaderFilter to tell JIP to instrument just your classes.

There are several prebuild ClassLoaderFilters that can be used:

You specify which class loader filter you want to use via the profile properties file:

ClassLoaderFilter.1=com.mentorgen.tools.profile.instrument.clfilter.StandardClassLoaderFilter
Writing your own is as simple as implementing the com.mentorgen.tools.profile.instrument.clfilter.ClassLoaderFilter interface. To do that, you'll need to find out which classloader is loading your code, which can be easily accomplished by adding this somewhere in your code:

System.out.println(Thread.currentThread().getContextClassLoader().getClass().getName());
If you create a ClassLoaderFilter if an enviroment that it's supported, please create a
feature request for it and attach your BSD licensed code. It will be greatfully included in the next release!

There is a simpler method for doing this that doesn't involve writting any code. The GenericClassLoaderFilter allows you to specify when Class Loaders to filter on in the profile properties file. To do this, first change your class loader filter:


ClassLoaderFilter.1=net.sourceforge.jiprof.instrument.clfilter.GenericClassLoaderFilter
(If you don't specify a class loader filter, JIP defaults to GenericClassLoaderFilter, so you could just as easily remove that property from the file).
Once you know which classloader(s) you want to use, put them in the profile properties file:

accept-class-loaders=org.apache.catalina.loader.StandardClassLoader,org.apache.catalina.loader.WebappClassLoader
If the classloader(s) your interested in implements an interface, you can specify that instead (in other words, the classes you specify don't need to be subclasses of java.lang.ClassLoader). In the example above, both Tomcat classloaders implement a common interface, so you could do this:

accept-class-loaders=org.apache.catalina.loader.Reloader

There is an additional mechansim that provides a finer level of control over which classes are profiled and which aren't. This is done via include and exclude lists. A list is a comma sperated list of packages or fully qualified class names. For example:


exlude=com.sun.tools.javac,org.apache.xerces.impl.XMLScanner
This will exclude from the profile all classes and packages in the com.sun.tools.javac package. In addition, the class org.apache.xerces.impl.XMLScanner will be excluded as well.
Include lists work the same way, only they tell the profiler what classes can be included. Note that the lists are applied to the classes that the ClassLoaderFilter accepts. So it further narrows what is profiled. Note also that if you use both an include and an exclude list, the include list is applied first. Be very careful when using both include and exclude. If a method that you want to see is called from a class that has been excluded, you will not see the call at all! Include lists are very tricky in this regard because they implicitly exclude classes and packages.

How do I specify the output file name?

Specify file=[name] in the profile properties file. The default is profile.txt which will be output in the JVM's working directory. You can even specify what type of output you'd like using the output property. This defaults to text but you can set if to xml or both. If you specify both, JIP will substitute "xml" as the extension for the file name of the xml file. In other words, if you say
file=profile.txt
output=both
you'll get two output files, profile.txt and profile.xml.

I've run JIP several times on my application and each time I get a different set of timings. Shouldn't they always be the same?

In a multiuser environment, even the performance of staticly compiled languages can vary. Java uses a runtime "Just In Time" compiler that observes how the code is being executed in order to use an optimal compilation strategy. This can lead to a variance in the time it takes a short running program to execute. Other factors such and disk and network IO can also contribute to the amount of time it takes a program to execute. These kinds of factors should be easy to spot in JIP's output.

You should be aware that there are two things that JIP doesn't measure:
  1. The execution of static initializers. JIP uses an internal call stack to measure the net execution time of methods. Static initializers aren't executed as part of a program's flow of control, but rather are executed when the JVM loads the class, so JIP doesn't measure them.
  2. JMV startup time and time the JVM spends loading classes.

When I exclude more classes/packages, JIP reports that the application is running faster. Why is that?

When you tell JIP to exclude a class or package, no instrumentation is done to those classes. Less profiling means lower overhead which makes everything run faster. While JIP does make an attempt to factor out its own overhead when taking measurements, nothing is perfect.

How can I profile interactively (after all, it is called the Java Interactive Profiler)?

Information on interactive profiling can be found here.

I'm running JIP, but I don't get any output.

First, make sure that JIP is actually running. If it is, you should see this output when the JVM starts:

Java Interactive Profiler: starting
If you don't see this, make sure that the JVM is being
invoked correctly.

If you can see that in the output, make sure that you're using the right ClassLoaderFilter and/or accept-class-loaders. Then look at what you're including and excluding and make sure it makes sense. If all of this looks good, add the following to your profile properties file:


debug=on
Then try to profile again. When the program starts up, you should see a bunch of messages in stdout that look like this:

INST    org/apache/tools/ant/RuntimeConfigurable        [sun.misc.Launcher$AppClassLoader]
INST    org/apache/tools/ant/Location   [sun.misc.Launcher$AppClassLoader]
INST    org/apache/tools/ant/helper/ProjectHelper2$RootHandler  [sun.misc.Launcher$AppClassLoader]
INST    org/apache/tools/ant/util/JAXPUtils     [sun.misc.Launcher$AppClassLoader]
skip    org/apache/xerces/jaxp/SAXParserFactoryImpl     [sun.misc.Launcher$AppClassLoader]
skip    org/apache/xerces/jaxp/SAXParserImpl    [sun.misc.Launcher$AppClassLoader]
INST indicates that the class in question has been instrumented. skip means that it has not. If you don't see any of this, then you're not pointing to the profile properties file that you think you are. If you're using a relative path to this file, you might want to try making it absolute. If all you see are skips, then something is wrong with the class loader filter you're using or the include/exclude lists.

If you're still having problems and you're using Unix or OS X, make sure you have permissions to the directory where the output file is configured to go.

If you're still having problems, post a message on the help forum. We're always happy to help out!

In the output I see something called an Interaction #. What is that?

The way that JIP profiles is by tracking call stacks. Each call stack is associated with a thread. There are circumstances under which you end up with more than one call stack associated with a given thread. This often happens in web apps where worker threads are pooled and reused across mutliple client requests. JIP calls these interactions. You also might start a profile in the middle of a thread executing. Once the flow of control makes it back to the place where it started, profiling must stop. Every time this happens, it's called an interaction.

I'm trying to profile the Extension class loader, but I'm getting a runtime exception.

You cannot profile classes that are loaded by the Extension classloader. When JIP instruments a class, it inserts a call to the runtime profiler. The runtime profiler class itself is loaded by the javaagent interface using the Application classloader. Extensions loaded classes cannot "see" classes loaded by the Application classloader. If you're trying to profile a standalone app and want to profile a class that's being loaded by the extensions classloader (i.e., -Djava.ext.dirs=[some-dir-with-my-jar]), move the jar file to the classpath.

The section of the output that lists the most expensive methods goes on and on. I really only care about the most expensive methods. Is there a way to limit what's output in this section?

You can do this with profile properties. Setting max-method-count to any positive integer will expressly limit the number of entries in this section of the output. -1 is the default, which means no limit. Setting this to compact will only display methods with a gross execution time of 10 (milliseconds) or more. You can control this with the method.compact.threshold.ms property.

The call trees in JIP's output can get pretty deep. Is there anyway I can control how deep they are?

There are a number of ways to do this, all of which use profile properties. The first is thread-depth which defaults to -1, which means no limit. Setting this to a positive integer will limit how deep the call tree is. If you set this property to compact, JIP will use a node's gross time to determine if it should be displayed. This value default is 10 (milliseconds) but can be changed using thread.compact.threshold.ms.

I don't care about the call graphs, I'm only interested in the summary information. Is there a way to turn off the call graph output?

Yup:

output-summary-only=yes

I'm running one profile after another an it's a real pain to have to rename the output file each time so that the next time I run a test, the old profile isn't overridden. Is there a way to get around this?

If you tell JIP to output to a directory (i.e., file=my-output-dir), JIP will output uniquely named files to that directory every time you run a profile.

Is there a way to use JIP to do heap analysis?

Nope. You can see how many objects of each class were created using track.object.alloc=on but that's no substitute for a good heap analysis tool.

I have a class that has two methods with the same name. Is there a way that I can see in method signature in the output?

Sure:

output-method-signatures=yes

Is there an easy to use JIP's output to do my own analysis?

JIP has an output option for outputting an XML document (output=xml). This contains all of the information that you get in a text output, but in a terse, but easy to parse XML format. This makes JIP a great tool to use if you have need to do custom analysis. In fact, someone created a GUI front-end for JIP that uses the XML output. It's pretty cool.

Does JIP have a GUI front end?

Yes! It's called jipViewer and can be found in the profile directory. It requires that when you profile your app, you generate an XML file output (output=xml or output=both).

Can I hook into JIP's instrumentation to collect my own runtime metrics?

Yes! JIP allows you to plug in your own runtime profiler. Here's how to do it:
  1. Create a class with the following methods (no need to implement an interface, nothing to inherit from -- total fredom!):
    
    public static void initProfiler()
    public static void start(String className, String methodName)
    public static void end(String className, String methodName)
    public static void alloc(String className)
    public static void beginWait(String className, String methodName)
    public static void endWait(String className, String methodName)
    public static void unwind(String className, String methodName, String exception)
    
    (beginWait and endWait are called when an object is waiting on a semaphore.) You might want to also add a
    shutdownHook so that your class will get notified when the JVM shutsdown.
  2. In your profile properties file, change profiler-class to point to your class.
JIP comes with 2 profilers. com.mentorgen.tools.profile.runtime.Profile is the one that's normally used. net.sourceforge.jiprof.timeline.TimeLineProfiler isn't really a profiler at all -- it's a tool to aid in the understanding of concurrency issues.

I'm having issues related to concurrency in my application, can I use JIP to give me a timeline of which methods are being called in different threads?

Yes! Change you profile properties to have the following:

profiler-class=net.sourceforge.jiprof.timeline.TimeLineProfiler
The output looks like this:

	...
	
	START	[9]	ProjectComponent:getProject()Lorg/apache/tools/ant/Project;	(org.apache.tools.ant)
	END	[9]	ProjectComponent:getProject()Lorg/apache/tools/ant/Project;	(org.apache.tools.ant)
	START	[9]	Project:log(Lorg/apache/tools/ant/Task;Ljava/lang/String;I)V	(org.apache.tools.ant)
Time: 3260 ms.
	START	[9]	Project:fireMessageLogged(Lorg/apache/tools/ant/Task;Ljava/lang/String;I)V	(org.apache.tools.ant)
	ALLOC	[9]	BuildEvent	(org.apache.tools.ant)
	START	[9]	BuildEvent:(Lorg/apache/tools/ant/Task;)V	(org.apache.tools.ant)
	START	[9]	ProjectComponent:getProject()Lorg/apache/tools/ant/Project;	(org.apache.tools.ant)
	END	[9]	ProjectComponent:getProject()Lorg/apache/tools/ant/Project;	(org.apache.tools.ant)
	START	[9]	Task:getOwningTarget()Lorg/apache/tools/ant/Target;	(org.apache.tools.ant)
	END	[9]	Task:getOwningTarget()Lorg/apache/tools/ant/Target;	(org.apache.tools.ant)
	END	[9]	BuildEvent:(Lorg/apache/tools/ant/Task;)V	(org.apache.tools.ant)
	
	...
Ledgend:
Time - This is the time, relative to the start of profiling, when the events listed were captured.
START - The given method was entered.
END - The given method was exited.
W:START - The given method started to wait on a mutex.
W:END - The given method ended its wait on a mutex.
ALLOC - An instance of the given class was created.
THROWS - An exception was thrown.
[x] - This is the id of the thread associated with the event.

Notes on usage:

- output-method-signatures can be used to display the full method signature.
- clock-resolution can be used to toggle the unit of time used to generate the timeline. You can use either ms for milliseconds or ns for nanoseconds. (Note that this property is not used by the standard profiler).
- As with the standard JIP profiler, tracking object allocations can be turned on or off by using track.object.alloc=on|off.
- Currently, the Timeline profiler only supports one output format, so the output property is ignored.
- You cannot use both the standard profiler and the timeline profiler at the same time.
- Output from the Timeline profiler can be very, very large.
- Currently, the interactive profiling is not supported.
- The ordering of method calls is correct within the context of a thread. Ordering is not guaranteed between threads.

I think my long running application has a memory leak. Is JIP the right tool to help with this?

Nope. JIP has no way to monitor what's happing in the heap.

I'm trying to profile an application interactively, but it's hard to start and stop the profiler at just the right time. Is there a way to explicitly tell JIP when to start and stop profiling?

If you're using the standard profiler, you can manipulate it programatically at runtime with the following static calls:

Profile.clear(); // initialises the profiler
Profile.start(); // starts the profiler
Profile.stop();  // stops the profiler
Profile.setFileName(String fileName); // changes the output file name
Profile.shutdown(); // shuts the profiler down.
Profile.shutdown() causes JIP to generate output. It's recommended that you call this right after calling Profile.stop();. You could also add a
shutdownHook that calls Profile.shutdown(). Note also that when doing explicit profiling, you should probably start the VM with profiler=off in your profile properties.



Copyright 2007, Andrew Wilcox.
Creative Commons License