How to use the new JRuby profiler
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.