This week I had a major success improving the performance of our application, thanks to some judicious use of JProfiler. The key was setting the filters correctly. This post will show you how to do that.
First, you need JProfiler. This is a commercial product You can get a ten-day evaluation license for free, and use what you learn to convince your managers to pay for a permanent one. Download the app and unzip it. I have version 7.
Second, create a profiling session. There are several ways to do this, and the documentation is not especially helpful. If I cover by experience in detail, it’ll be in a separate post. One way or another, hook up to a JVM. Get the profiling going, because you can’t set up the filters properly until it’s hooked up. If it asks you to choose between Instrumentation or Sampling, pick Instrumentation. As it points out (in JProfiler7), good filters are critical for instrumentation, and filters are the focus of this post.
Before you get serious with the profiling, give the filters a useful initial setting. This is key to weeding out the garbage. Visit the Session Settings (button along the top toolbar). In there, pick Filter Settings (button along the left toolbar).
Initially, the filters are set up with some default excludes. Change this — push the green “+” button on the right, and from the popup menu pick “Add filters from package browser.” (This won’t work if the profiling session is not connected to an app, because it needs to query the java process for its classpath.)
Now comes the critical part: selecting the classes we care about. It’s tempting to pick all kinds of interesting ones, but start small. Choose only the packages you can change. Basically, expand the com node, find your company’s name, and check that. If there’s another package that holds code controlled by your team or your organization, check that too. Leave everything else unchecked. Focus on what you control!
Click OK on that. On the filters page, make sure that old Excluded filter is gone and only your Included filter (or filters) remains.
Once you click OK on the Session Settings and select “Apply Now”, magic happens. The code in your running application is re-instrumented so that classes selected by your filters record their activities.
Here’s the trick about the filters: the instrumentation will record the time spent in your methods (the ones included by the filter) and the time spent in all methods directly called by those methods. That way it knows how to divide the bar into dark red and bright red for all the methods in your code.
Proceed with profiling! You want the CPU View (left-hand toolbar). Start recording CPU if necessary. Make your app do the slow thing it does. Stop CPU profiling.
Now for the delicate bit, where I can’t show you screenshots because of improprietary. The CPU view shows you a big tree of where your app spends its time. There are bars next to each method name. The longer the bar, the more time it’s spending there. There are two components in the bar: dark-red and bright red. (At the top level, it’s all dark red.) Bright-red represents the time spent within this method, and dark-red is the time spent in methods called by this method.
Find the long bar at the top and expand the node. Keep expanding the long bar until you get to something with a significant amount of bright red. Here’s your offender.
If the method that’s bright red is something low-level like reading a stream, you’re not going to make that faster. Move up the stack trace (that is, the big tree of method calls) and look at your own code. Think about how you can do less of whatever operation is taking so long.
If the method that’s bright red is higher-level, such as a Spring class, then we might be able to do something about all that slowness. We can get deeper into what it’s doing by refining the filters. Say, for example, a lot of time is spent in org.springframework.context.support.ClassPathXmlApplicationContext.refresh(). That’s reading a configuration file, so we have control over what it’s doing. That method has a whole slew of method calls inside it, any one of which could be slow. To find out more, it’s time to refine the filters.
Go back to your session settings, filter settings, and add an inclusive filter for the package containing the bright-red class, such as org.springframework.context.support. (Pitfall – if you do this by typing in the name of the package, put a period after the package name. It won’t work without it.)
With the new filter settings, do the slow thing again. (You probably need to close your app and start from the beginning.) Now you can drill down further and see where the slowness happens. Repeat if necessary.
In my case, I modified the filters a few more times before the stack trace showed me that the time was being spent loading up files for a component scan. It loaded a few hundred files from the jar, just to choose eight based on annotations. Narrowing the component scan improved application time by 40%, and replacing it with explicit bean definition helps even more. This was a big victory for JProfiler.