Low Overhead Method Profiling with Java Mission Control

With the Hotspot JDK 7u40 there is a nifty new tool called Java Mission Control. Users of the nifty old tool JRockit Mission Control will recognize a lot of the features. This blog focuses on the Flight Recorder tool, and the method profiling information you can get from the flight recorder.

So you want to know why all your CPUs are saturated. Perhaps you even want to get some hints as to what changes can be done to your application to make it less CPU-hungry. Don’t despair – Java Mission Control to the rescue!

Built into the HotSpot JVM is something called the Java Flight Recorder. It records a lot of information about/from the JVM runtime, and can be thought of as similar to the Data Flight Recorders you find in modern airplanes. You normally use the Flight Recorder to find out what was happening in your JVM when something went wrong, but it is also a pretty awesome tool for production time profiling. Since Mission Control (using the default templates) normally don’t cause more than a per cent overhead, you can use it on your production server.

Getting the Data

So, to do method profiling with JMC, simply go about producing a recording like you normally would. Here is an example:

  1. Start the application you want to profile with the following arguments to enable the flight recorder:
     -XX:+UnlockCommercialFeatures -XX:+FlightRecorder 
  2. Next start Mission Control. You can just double click on jmc in the bin folder of your 7u40 JDK.
  3. (Close the Welcome screen if this is your first time starting JMC.)
  4. Right click on the JVM you wish to start a flight recording on in the JVM browser and select Start Flight Recording.
    StartFlightRecording
  5. Leave all the default settings and select the ‘Profiling – on server’ template for your Event Settings. You can usually just hit finish at this point, but I’d like to talk a bit on how you can control the method sampler.
  6. Click Next to go to the higher level event settings. These are groupings of named settings in the template. Here you can select how often you want JFR to sample methods by changing the Method Sampling setting.
    MethodSamplingSettings
  7. If this level of granularity is not enough, you can click next and modify the event settings on a per event type basis. Type Method in the filter text box.
    MethodSamplingAdvanced
    Note that you can go back and forth between the previous wizard page to find out what the high level settings really represent.
  8. When satisfied, click finished. The recording will be downloaded automatically and displayed in Mission Control. Click the tab group for Code to start visualizing your Method Profiling Sample events.
    SpecJBBMethodOverview
    (Since Java 2D hardly produces any load on my machine, I actually switched to a SpecJBB recording here. Blinkar )
    On this tab you get a overview breakdown of where the JVM is spending the most time executing your application.
  9. Switch to the method profiling tab to find a top list of the hottest methods in your application.
    image
    The top ones are usually a good place to start optimizing.

Optimization

Once you’ve found your top methods, you either want to make sure that these methods are faster to execute, or that you call the method less. To find out how to call the method less, you normally look for ways to call along the predecessor stack traces less, and you look for the closest frame that you can change. It is quite common that the case is that some JDK core class and method is among the top methods.

Since you cannot rewrite, say, HashMap.getEntry(), you need to search along the path for something that you can change/control. In my recording, the next one is HashMap.get(), which does not help much. The next one after that might be a good candidate for optimization. An alternative would be to find somewhere along the entire path where we can reduce the number of times we need to call down to get whatever we need to get from the HashMap.

After you’ve done your optimizations you do a new recording to see if something else has popped up to the top. Notice that it really doesn’t matter exactly how much faster the method itself became. The only interesting characteristic is the relative time you spend executing that part of the Java code. It gives you a rough estimate of the maximum performance gain you can get from optimizing that method.

Command Line Flags

Aside from the normal command line flags to control the FlightRecorder (see this blog), there are some flags that are especially useful in the context of the method sampling events.

There is one flag you can use to control whether the method profiler should be available at all:

-XX:FlightRecorderOptions=samplethreads=[true|false]

There is also a flag to limit the stack depth for the stack traces. This is a performance optimization and a safety, so that the performance hit doesn’t run away, say if you have an insane stack depth and a lot of deep recursive calls. I believe it is set to 64 by default:

-XX:FlightRecorderOptions=stackdepth=<the wanted stack depth>

Limitations

The Flight Recorder method profiler is quite good at describing where the JVM is spending the the most time executing Java code at a very low overhead. There are, however, some limitations/caveats that can be useful to know about:

  1. If you have no CPU load, do not care too much about what the method profiling information tells you. You will get way fewer sample points, not to mention that the application may behave quite differently under load. Now, should your application be under heavy load and you still aren’t saturating the CPU, you should probably go check your latency events.
  2. The method profiler will not show you, or care about, time spent in native. If you happen to have a very low JVM generated CPU load and a high machine CPU load in your recording, you may be spending quite a lot of time in some native library.

Further reading and useful links

Related Blogs:
Java Mission Control Finally Released
My JavaOne 2013 Sessions

The Mission Control home page:
http://oracle.com/missioncontrol

Mission Control Base update site for Eclipse:
http://download.oracle.com/technology/products/missioncontrol/updatesites/base/5.2.0/eclipse/

Mission Control Experimental update site (Mission Control plug-ins):
http://download.oracle.com/technology/products/missioncontrol/updatesites/experimental/5.2.0/eclipse/

The Mission Control Facebook Community Page (not kidding):
http://www.facebook.com/pages/Java-Mission-Control/275169442493206

Mission Control on Twitter:
@javamissionctrl

Me on Twitter:
@hirt

8 Responses to "Low Overhead Method Profiling with Java Mission Control"

  1. […] the last blog entry about the method profiler I showed that Mission Control can be quite useful for profiling production systems. However, I only […]

  2. Carfield Yim says:

    There is already sample base profiling from VisualVM, what is the advantage of Java Mission Control over the sample base profiling from VisualVM? Sound like that one is already low overhead also?

  3. Marcus says:

    Hi Carfield,

    I am not 100% sure what Visual VM uses. I do know that Google uses the unsupported AsyncGetCallTrace for their profiler. The method profiling in Java Flight Recorder is based upon AsyncGetCallTrace, but improved to meet the needs for low overhead profiling in production. This work has been of benefit for the old unsupported AsyncGetCallTrace too, as some of the work to harden the Flight Recorder profiler has gone back into the old AsyncGetCallTrace.

    Aside from that, there is an immense benefit in being able to correlate what you get from the method profiler to everything else you get from the Flight Recordings.

    Since Oracle is offering you both alternatives, and they are both free in development, you can simply pick the one that suits you the best.

    Kind regards,
    Marcus

  4. Carfield Yim says:

    Thanks a lot Marcus and I will try that out

  5. Adrian Bartlett says:

    Hi Marcus the Flight Recorder/Mission Control feature for Oracle Java SE looks great.

    I am hoping to use the Flight Recorder to capture all method calls, by setting “Method Profiling Sample” to 0ms and “Method Sampling Information” to 0ms. I want to use this information (com.jrockit.mc.flightrecorder API), to construct sequence diagrams, and obtain an understanding of how the software under study operates.

    Is this possible, or is bytecode instrumentation the only option I have?

  6. admin says:

    Hi Adrian,

    No, it’s not possible to use the Method Profiling events like that. A JPLIS agent (BCI) or a JVMTI agent are your best bets.

    /M

  7. ming qin says:

    Hi Marcus: My window xp 32-bit PC runs JDK1.7_45 , using mission control 5.2′s flight recorder to pinpoint heavy executing code blocks by using Hot Methods and Call Tress features. The result display of either predeceeors in Hot Methods or call tress don’t indicate the my source code line number but showing stack trace , sample count , percentage.
    How difficult will that be to add showing users’ application source code line number to be part information of stack trace?
    A few java profilers seem to be able to do that. I don’t know how those profilers implement that feature. Interesting enough that, most of them require JDK1.5 above.

  8. Marcus says:

    Hi Ming,

    You can get the source line even in that version of Mission Control, though it is a bit cumbersome. Simply add the samples you are interested in to the operative set, then show the operative set in the log view. Select one of the samples, and the stack trace shown in the event details will show line numbers. That said, line numbers are shown properly in all traces in JMC 5.4.0 (to be available with JDK 8u20).

    Kind regards,
    Marcus

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>