danlucraft

How to use the new JRuby profiler

March 2011

The JRuby team released version 1.6 yesterday, with lots of improvements and fixes. My contribution was extending the profiler with a graph mode and a Ruby API (with a lot of help from Headius :)) This profiler is built-in to the JRuby interpreter, no installation necessary!

(BTW, hacking on JRuby is extremely easy if you know only a little Java. You can download the source, run ant, and start fiddling with things instantly. If you have any interest in learning about compilers and interpreters it’s a great place to start.)

Profiling a script

JRuby 1.5 included the --profile option, which profiles all Ruby code run during the JRuby execution and outputs a flat profile:

> jruby --profile my_script.rb

Total time: 0.96

     total        self    children       calls  method
----------------------------------------------------------------
      0.61        0.01        0.61          15  Kernel#require
      0.32        0.00        0.32           1  A#foo
      0.32        0.19        0.13           1  Fixnum#times

In 1.6.0 there is now an additional profiling flag --profile.graph, which outputs a profile graph breaking down times by callers and callees:

> jruby --profile.graph my_script.rb

Total time: 0.90

 %total   %self       total        self    children                 calls  name
---------------------------------------------------------------------------------------------------------
   100%      0%        0.90        0.00        0.90                     0  (top)
                       0.57        0.01        0.56                  1/15  Kernel#require
                       0.31        0.00        0.31                   1/1  A#foo
---------------------------------------------------------------------------------------------------------
                       0.31        0.00        0.31                   1/1  (top)
    34%      0%        0.31        0.00        0.31                     1  A#foo
                       0.31        0.23        0.08                   1/1  Fixnum#times
---------------------------------------------------------------------------------------------------------
                       0.31        0.23        0.08                   1/1  A#foo
    34%     25%        0.31        0.23        0.08                     1  Fixnum#times
                       0.05        0.05        0.00         100000/100000  Array#length
                       0.03        0.03        0.00         100000/100000  Array#<<
---------------------------------------------------------------------------------------------------------

For a detailed description of the format of these outputs, see the ruby-prof documentation here and here.

How to profile blocks of code

Both the --profile and --profile.graph options will profile all of the Ruby code executed by JRuby. You might like to be more specific and only profile a particular block of JRuby code.

For this you can pass the flag --profile.api and use the Ruby API to the profiler. The flag is necessary to turn on the instrumentation, without it this code will work but return no data:

# run me with: jruby --profile.api ...

require 'jruby/profiler'

profile_data = JRuby::Profiler.profile do
  # code to be profiled ...
end

profile_printer = JRuby::Profiler::GraphProfilePrinter.new(profile_data)
profile_printer.printProfile(STDOUT)

You can also use the JRuby::Profiler::FlatProfilerPrinter instead. This will print the profile output to stdout.

If you would like to save the result to a Ruby String, here is a snippet of how to do that.

What is profiled?

At the moment, the profiler has just one measure mode, which is wall time. This has several drawbacks:

It’s important to keep these two points in mind when profiling your code.

Adding new measure modes is a priority for the next version, and should address these drawbacks.

Overhead

At the moment, running either of the profiling modes will slow down your code between 50% and 100%.

Improvements

As well as new measure modes (cputime, thread time and allocations), I’m hoping to add support for HTML output in the next version.

blog comments powered by Disqus