Profiling Ruby

To monitor a Ruby script performance you have many possible tools let’s go through them.

Benchmark

This is a built-in library and it’s fairly simple (and limited):

require 'benchmark'

Benchmark.bm do |b|
  b.report("sum") do
    100.times do
      1 + 1
    end
  end
end

Output:

      user     system      total        real
sum  0.000000   0.000000   0.000000 (  0.000031)

Let’s try something more interesting:

require 'benchmark'

Benchmark.bm do |b|
  n = 1_000_000
  b.report("x = {}") do
    n.times do
      x = {}
    end
  end

  b.report("x = Hash.new") do
    n.times do
      x = Hash.new
    end
  end
end

Output:

      user     system      total        real
x = {}  0.340000   0.000000   0.340000 (  0.339039)
x = Hash.new  0.550000   0.000000   0.550000 (  0.553914)

ruby-prof

This is a relatively old library. Once you’ve installed the ruby-prof gem you can use it in two ways: as a command line tool and through its API inside the script you want to profile.

Command line usage

It’s fairly simple:

ruby-prof script.rb

This is what we get with a one-line puts 'hello':

hello
Thread ID: 70284745066960
Total: 0.000123
Sort by: self_time

 %self      total      self      wait     child     calls  name
 43.09      0.000     0.000     0.000     0.000        2   IO#set_encoding
 17.89      0.000     0.000     0.000     0.000        1   Kernel#puts
 17.89      0.000     0.000     0.000     0.000        2   IO#write
 17.07      0.000     0.000     0.000     0.000        2   Global#[No method]
  4.07      0.000     0.000     0.000     0.000        1   IO#puts

* indicates recursively called methods

API usage

Add in your code something like this:

require 'ruby-prof'
RubyProf.start
...
result = RubyProf.stop
# Print a flat profile to text
printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

And this is what we get:

hello
Thread ID: 70135880829400
Total: 0.000116
Sort by: self_time

 %self      total      self      wait     child     calls  name
 62.07      0.000     0.000     0.000     0.000        1   Global#[No method]
 18.97      0.000     0.000     0.000     0.000        2   IO#write
 12.93      0.000     0.000     0.000     0.000        1   Kernel#puts
  6.03      0.000     0.000     0.000     0.000        1   IO#puts

* indicates recursively called methods

You can also enclose the code to profile in a block:

require 'ruby-prof'
result = RubyProf.profile do
...
end
# Print a flat profile to text
printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

output types

FlatPrinter is the simplest; the available printers are:

The graph profile is one of the most interesting, its output format is well described here:

https://github.com/rdp/ruby-prof/blob/master/examples/graph.txt

perftools.rb

This is a Ruby adaptation of Google’s perftool library.