Profiling JRuby with NetBeans


26 October 2012

A case study and tutorial on using the NetBeans profiler to profile Ruby code running on the JVM via JRuby. Walks through the steps of configuring NetBeans, launching JRuby with profiling settings, connecting NetBeans to JRuby, and analyzing the results.

NetBeans IDE for Java includes a Java profiler. I like using this to profile JRuby code, though it took me a while to get the hang of things and extract useful information.

Setting up NetBeans

Export Remote Profiling Pack (Only needs to be done once)

After installing NetBeans, the first step is to set export the “remote profiling pack” so we can use the NetBeans profiler in “remote” mode. Even though NetBeans and JRuby will both be running on the same machine, I find “remote” mode the most convenient method: start JRuby with some special Java options, direct NetBeans to connect, then gather profiling data.

Start NetBeans and select Profile -> Attach Profiler.... If the Attach Wizard does not appear, click the change link to change the Attach Mode. Select Application with Remote and Direct options.

Click Next to move to the Remote System page. Set to “localhost”.

Do not click Finish; instead, click Next to move to Manual Integration page. Choose “Java SE 7.0” and click Generate Remote Pack. Save the resulting file somewhere such as $HOME/netbeans/remote-pack. Unzip the resulting file:

~/netbeans/remote-pack$ unzip profiler-server-mac.zip

Configure for Remote Profiling with JRuby filter

Now the Attach Profiler dialog should be configured to profile a “remote” application running on localhost. Sampling mode is best to start out with. NetBeans will periodically sample the stacks of all threads, recoding the stacktraces. It can only make estimates of the timings and counts of method calls, but this is often good enough and is far lower overhead than full Profiling which modifies Java bytecode to add instrumentation.

Click Edit Filter Sets and add a new filter. Set the type to Inclusive, and click Edit Global Filters to create a filter that applies to org.jruby., rubyjit.. This will limit profiling to Java classes in these packages. JRuby internals and JRuby running as an interpreter will be using mostly org.jruby.. When JRuby JIT compiles Ruby code into Java, this will appear under the rubyjit. package.

At this point we’ll leave NetBeans until we have our ruby code ready to profile.

Running JRuby with Profiling Options

To use the NetBeans remote profiler, Java must be started with commandline options to hook in the NetBeans remote pack code into the JVM startup. The options are -agentpath:$agentpath=$remote_pack_lib/lib,5140 where $agentpath is the path to the appropriate file inside the remote pack (varies by platform), $remote_pack is the path to the lib directory in the remote pack, and 5140 is the TCP port on which to listen (NetBeans’ default is 5140).

Since JRuby will read the JAVA_OPTS environment variable and apply them to the JVM, a small shell script can be used to wrap JRuby invocations, called netbeans-profile

#!/bin/sh

remote_pack_lib="$HOME/netbeans/remote-pack/lib"
agentpath="$remote_pack_lib/deployed/jdk16/mac/libprofilerinterface.jnilib"
opts="-agentpath:$agentpath=$remote_pack_lib,5140"

export JAVA_OPTS="$JAVA_OPTS $opts"
exec "$@"

If this script is on your PATH and made executable, you can launch JRuby like this to start a profiling session:

netbeans-profile jruby -G -S rake assets:precompile

The -G instructs JRuby to load Gemfile. Note that using bundle exec will not work correctly since two JVMs are launched: the first to set up the gem environment, and the second to run the actual JRuby command.

With the NetBeans profile options in place in the JVM, you should see something like this:

$ netbeans-profile jruby -G -S rake assets:precompile
Profiler Agent: Initializing...
Profiler Agent: Options: >$HOME/netbeans/remote-pack/lib,5140<
Profiler Agent: Initialized successfully
Profiler Agent: Waiting for connection on port 5140 (Protocol version: 12)

The JVM is waiting a connection from NetBeans, so lets return to NetBeans and start a profiling session.

Profiling in NetBeans

Start NetBeans and select Profile > Attach Profiler.... If you followed the steps above, it should already be configured to profile a “remote” application running on localhost. Make sure the filter options are set to your taste, then click Attach. The JRuby command that was paused waiting for NetBeans should now proceed.

While the program is running, you can click Take Snapshot to snapshot the profiling data acquired thus far. This is most useful in long-running sessions like testing a Rails application. Or, if you wait until the JRuby command has exited, NetBeans will offer to make a snapshot at that point.

With a snapshot loaded, NetBeans will show the Call Tree view. This is a list of all Java threads that were seen along with a tree of method calls. Switch to the Hot Spots view and sort by Self Time (cpu). In the example, java.lang.Thread.getStackTrace() is consuming 20% of the time and has been invoked 2588 times. But this fact doesn’t do much good since that method is out of our control. We need to know what methods are resulting in eventual calls to getStackTrace().

Right-click on the getStackTrace() line and select Show Back Traces. This will open an overwhelming view of all code paths that lead up to calls to getStackTrace().

Looking at rubyjit method calls in the profiler, it is usually very easy to determine which Ruby method is being called. However, in the Java side there are a few Java method calls in between each Ruby method call. This makes digging through a large tree of back traces a little tedious.

Nevertheless, we soldier on. Notice how the number of invocations on the right column starts at 2588 and then at a point, falls to 93. This indicates that those portions of the tree are responsible for only 93 of the 2588 total invocations. Collapse that portion of the tree for now, since it is less important than the biggest offenders.

By expanding or collapsing the tree at the points where the invocation count drops off, we can zoom in on a section responsible for 984 of the 2588. Zooming down further, we finally see familiar looking method names such as rubyjit.FileUtils$$mkdir_p.... This is a JIT’ed method from FileUtils.mkdir_p.

Notice above that the method org.jruby.ast.FCallTwoArgNode.interpret is responsible for 73 invocations. This is JRuby acting as an interpreter before it has JIT compiled the method. To avoid interpreter calls cluttering up the profile (the Java profiler cannot know what Ruby method was being called), JRuby can be configured to compile everything upfront, or in a long-running app you can simply wait for a time to allow the JIT to work automatically.

Finally, we can peek inside the code for FileUtils to see why it might be triggering exceptions. Obviously, the means of improving performance may vary drastically from codebase to codebase. In this particular case, several bits of Ruby including FileUtils use exceptions for flow control where, at least during an assets precompilation run, the exceptional cases are common enough to take up a large portion of the time. See Comparing Ruby exceptions to additional stat() test for more details on that particular issue.