Profile and ruby-prof: Getting Specific

I'll close up my profiling trilogy with a little bit about profiling parts of your Ruby code. While ruby -r profile my_program or ruby-prof my_program are great for 90% of what you want to do, there's always the odd time that you really only care about one specific portion of your code — for example, if you're doing IO or setup tasks that you don't want to muddle your profile.

The Profiler__ library is the stock Ruby way of doing this, so let's look at this option first. Profiler__ has three methods that will be of interest to us:

• start_profile — which starts collecting data
• stop_profile — which stops data collection
• print_profile — which prints the collected data (it takes a parameter naming the filehandle to which it should print the data)

Say you had an rwb test script that looked like this (yes, I know I've depracated rwb, that doesn't mean I can't use it in a contrived little example):

require 'rwb'
urls = RWB::Builder.new()
urls.add_url(10, "http://localhost")
tests = RWB::Runner.new(urls, 1000, 200)
tests.run
tests.report_header
tests.report_overall

Profiling this would be a nightmare, it relies on net/http and makes several gazillion calls to the Ruby Builtin and Standard Libraries — all these calls would dominate the run and resulting profile, the stuff you really care about (and can fix) would be buried. If I just wanted to profile the reporting functions, I could modify the test script to look like this:

require 'rwb'
require 'profiler'
urls = RWB::Builder.new()
urls.add_url(10, "http://localhost")
tests = RWB::Runner.new(urls, 1000, 200)
tests.run
Profiler__::start_profile
tests.report_header
tests.report_overall
Profiler__::stop_profile
Profiler__::print_profile($stderr)

This generates output like that below (edited to show the % time, cumulative seconds and name fields of the top twenty lines):

  %   cumulative
 time   seconds  name
 40.00     0.22  Array#each
 20.00     0.33  Array#sort
 18.18     0.43  Float#<=>
 10.91     0.49  Array#push
  3.64     0.51  Float#+
  3.64     0.53  Float#**
  1.82     0.54  Float#-
  1.82     0.55  RWB::Runner#report_heade
  0.00     0.55  Float#to_f
  0.00     0.55  RWB::Runner#results_mean
  0.00     0.55  Math.sqrt
  0.00     0.55  Class#new
  0.00     0.55  Fixnum#/
  0.00     0.55  Array#shift
  0.00     0.55  Array#initialize
  0.00     0.55  Array#[]
  0.00     0.55  Kernel.puts
  0.00     0.55  Float#to_s
  0.00     0.55  RWB::Runner#report_overa
  0.00     0.55  Fixnum#+

Which differs considerably from a profile of the entire script created with the -r profile command line option. The first twenty lines are shown here for comparison (edited as above):

  %   cumulative
 time   seconds  name
113.58    18.73  TCPSocket#initialize
 92.06    33.91  Fixnum#==
  7.52    35.15  Kernel.catch
  7.16    36.33  RWB::Runner#run_test
  7.03    37.49  RWB::Builder#get_url
  6.61    38.58  URI.split
  5.82    39.54  Net::HTTP#Proxy
  5.34    40.42  Hash#include?
  5.15    41.27  Kernel.block_given?
  4.79    42.06  URI::HTTP#initialize
  4.49    42.80  URI::Generic#find_proxy
  4.37    43.52  Net::HTTP#new
  4.12    44.20  Kernel.class
  4.06    44.87  Kernel.open
  3.88    45.51  URI::Generic#split_userinfo
  3.82    46.14  OpenURI.open_loop
  3.82    46.77  Net::HTTP#do_start
  3.76    47.39  RWB::Result#initialize
  3.40    47.95  Net::HTTP#initialize
  3.09    48.46  RWB::Runner#run_thread
  3.03    48.96  ENV.include?

(And yes, there is a rounding/floating point/addition error in the second example ... I know it's there, but haven't bothered to dig into the exact cause.)

One thing to watch out for is that Profiler__ will happily overwrite any existing profile data if Profiler__::start_profile gets called multiple times.

ruby-prof provides similar control over what gets profiled — actually, it provides more options. It uses the methods:

• start — starts a new profiling run
• stop — stops the current profiling run and returns the data
• profile — allows you to profile a block passed in to it

Printing is handled a bit differently though, Report objects are created, and then printed through a print method. Each kind of report has it's own Class:

• RubyProf::FlatPrinter — a traditional profiling report
• RubyProf::GraphPrinter — a call graph profiling report
• RubyProf::GraphHtmlPrinter — an html call graph profiling report

Each of these classes has a print method, which takes two (optional) parameters — the output file handle and the minimum %self that a method call must take up to be printed.

We can recreate the above example like this:

require 'rwb'
require 'ruby-prof'
urls = RWB::Builder.new()
urls.add_url(10, "http://localhost")
tests = RWB::Runner.new(urls, 1000, 200)
tests.run
RubyProf.start
tests.report_header
tests.report_overall
result = RubyProf.stop
printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT, 0)

Changing it to print a call graph just means changing the second to last line to this:
printer = RubyProf::GraphPrinter.new(result)

While these may not be the kinds of profiling tasks you do every day, it's nice to know that they're there.

Happy Hacking!

If you found this post helpful, you might want to look at my ruby-prof post collection.