Tuesday, May 10, 2011

Profiling Tomcat with VisualVM on Mac OS X

I spent some time this last weekend (working on Mother's day - I'm terrible!) trying to figure out what was killing the performance of a particular operation in our tomcat application. This quest led me to do battle with a few bugs in the latest version of Java on Mac to get VisualVM profiling tomcat apps nicely.

VisualVM is included on Mac - you can fire it up by running `jvisualvm` in Terminal. It can attach to a VM in a couple of ways: locally, or over JMX. Either way requires a bit of fiddling. I got JMX working first, but apparently the instrumenting profiler doesn't work that way (maybe just for me?). There is a sampling profiler that works over JMX, but it only shows hot spots (methods with highest self time), not a call tree, and the hot spot information didn't help much with my issue.

UPDATE: I was wrong here. Call tree seems to work fine with the sampling profiler, just need to take a snapshot as a commenter pointed out, just like with the profiler. I still have the memory button grayed out with the sampler over JMX, so setting up the local option may be needed there or when you want to use the instrumenting profiler to get more precise data than the sampler can provide (but also poorer performance when profiling - see here)

 So I had to figure out how to connect locally as well. Here's what I found on both:

JMX Connection:
For this we just need to set the right JVM options before we start tomcat to enable JMX and allow VisualVM to connect without making us mess with authentication. Very bad idea on a production machine, but fine for development. Running the following before starting tomcat did the trick:
export JAVA_OPTS="-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=8086 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false"
At this point you should be able to fire up VisualVM, chose File -> Add JMX Connection, put in localhost:8086 and connect.

Local:
Turns out that VisualVM finds local VMs to attach to through data in directories called hsperfdata_{current user's name} that java applications create in the directory specified by the property java.io.tmpdir if the option -XX:+UsePerfData is on. It looks like its on by default for me. On Mac, java.io.tmpdir defaults to /tmp, so that is where VisualVM is looking for these files. Tomcat however uses its own temp directory, at temp under your tomcat install. This gets a little more complex because it used to be that no matter what you set java.io.tmpdir to, java would still put the hsperfdata directories in the system tmp so that things like VisualVM could find it - its only in Java 6 update 24 that it gets put in the user specified temp directory. So this will become irrelevant when the next update is released and pushed out by Apple for Macs.

The bug report for the JVM is here:
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7009828

In the mean time, one way to work around this issue is to point VisualVM to the temp directory you are actually using with the -J-Djava.io.tmpdir option. So start up VisualVM like this:
jvisualvm -J-Djava.io.tmpdir=$CATALINA_HOME/temp

replacing $CATALINA_HOME with the path to your tomcat install.

I ran into one final complication here: It looks like tomcat sets java.io.tmpdir to $CATALINA_BASE/temp without a trailing slash. I found that this caused the jvm make folders like temphsperfdata_{username}, rather than put a hsperfdata_{username} folder in the temp directory. So finally, run
export CATALINA_TMPDIR=$CATALINA_HOME/temp/

again replacing $CATALINA_HOME with the path to your tomcat install. Be sure to include the trailing slash. At long last, I was able to fire up tomcat and VisualVM, see tomcat listed under the "local" section and run the profiler!


5 comments:

  1. Awesome, Michael, nice blobbing.

    I took at stab at your local setup instructions and got things almost working, but my process is listed as (pid xxx) - it gets the correct pid - and the main window says Not supported for this JVM. Am using java version "1.6.0_24"
    Java(TM) SE Runtime Environment (build 1.6.0_24-b07-334-10M3326)
    Java HotSpot(TM) 64-Bit Server VM (build 19.1-b02-334, mixed mode)

    What jvm are you running? Goggling yields not much! A few promising hits that aren't, including one guy that blames this problem on an underscore in his username (not me). I'll look at it more tomorrow, no urgency from me here. Nighty

    ReplyDelete
  2. I'm using 1.6.0_24, and that is the only JVM installed on my machine. Might you have both 1.5 and 1.6 on yours? My best guess is that you might be running tomcat in 1.6 and jvisualvm in 1.5 or vice versa. If you look at the VisualVM process in itself, you can check the version it is running under. I only have 1.6 and I export JAVA_HOME in my .profile so I'm pretty safe from version mix ups. Beyond that, I can only suggest checking the permissions on your tomcat temp folder and the hsperfdata folders to ensure that jvisualvm can read (maybe write?) it.

    ReplyDelete
  3. Both instrumenting and sampling profilers in VisualVM show call trees, you have to take a snapshot first. See http://blogs.oracle.com/nbprofiler/entry/profiling_with_visualvm_part_1.

    ReplyDelete
  4. Thanks - just missed that as I hadn't yet spent much time with the app. It looks like I can't do memory profiling over JMX, so the local setup may still be useful.

    ReplyDelete
  5. Perfect! I think it's worth mentioning that that final command to run visual-vm / tomcat for local profiling was: "jvisualvm -J-Djava.io.tmpdir=$CATALINA_TMPDIR"

    ReplyDelete