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.
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.
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
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 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
#!/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" ORIG_JAVA_OPTS="$JAVA_OPTS" export JAVA_OPTS="$JAVA_OPTS $opts" "$@" JAVA_OPTS="$ORIG_JAVA_OPTS"
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
-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
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
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
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.