danlucraft /blog

How to use the new JRuby profiler

March 2011 • Daniel Lucraft

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:

  • heavy system load will change the timings of your code
  • threads will interfere with each others timings, meaning that results for multithreaded code will not be accurate.

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