Getting the Most from Your Tools

Using Ruby’s Benchmark library in order to measure the running time of a certain piece of code is easy enough to do, but the true strength of the Benchmark library lies a bit deeper. Take, for example, the return value of Benchmark.measure. If you print the return value, you can get a rundown of how long your code took to run:

require 'benchmark'

sum = 0
result = Benchmark.measure do
  1.upto(1_000_000) { |i| sum += i }
end

puts result

> ruby count.rb 
  0.100000   0.000000   0.100000 (  0.101773)

However, this return value is not just a simple string. It is a very capable instance of the Benchmark::Tms class. This class contains not only methods to report benchmark results, but also a number of utility methods to assist with more complicated benchmarking. For example, if you wanted to get an average from running a benchmark multiple times, but you didn’t want to contaminate your benchmark results with the time it takes to actually iterate, you could write something like the following:

require 'benchmark'

puts "How many times should I run the benchmark? "
itr = gets.chomp.to_i

result = Benchmark::Tms.new
itr.times do
  result += Benchmark.measure do
    sum = 0
    1.upto(1_000_000) { |i| sum += i }
  end
end

result /= itr
puts Benchmark::Tms::CAPTION
puts result

> ruby count.rb 
How many times should I run the benchmark? 
10
      user     system      total        real
  0.095000   0.001000   0.096000 (  0.095952)

All of the usual mathematical operators are available to work with instances of Benchmark::Tms. Additionally, as demonstrated in the code above, the Benchmark::Tms::CAPTION constant is available to make the display of benchmark numbers a bit nicer. Be sure to check out the documentation for all the details.

Boiling Away the Boilerplate

Certainly, the features provided by Benchmark.measure and the Benchmark::Tms class are useful, but it is a bit annoying to have to manage the running of benchmarks and outputting of results by hand. Ruby is famous for its ability to cut through boiler plate and do things simply. Surely there must be an easier way to work with the Benchmark library?

In fact, there is. The Benchmark.benchmark and Benchmark.bm methods make it even more convenient to benchmark a section of code. The way these methods work is slightly different than other APIs you may be familiar with, though. Both take a block as an argument, but they pass to the block another variable which you then use to benchmark other blocks of code. While it might sound complicated, a code sample is worth a thousand words:

require 'benchmark'

Benchmark.bm do |x|
  sum = 0
  x.report do
   1.upto(1_000_000) { |i| sum += i }
  end
end

> ruby count.rb
       user     system      total        real
   0.600000   0.080000   0.680000 (  0.168000)

Notice that the Benchmark.bm method handles the generation and formatting of output for us this time. While this may not seem like such a big deal when running only one test, it can be very handy when running multiple tests. Additionally, the report method takes an optional label argument, which can really help with keeping track of benchmark results:

require 'benchmark'

Benchmark.bm(11) do |x|
  x.report('append')      { a = ''; 10_000.times { a << 'a' } }
  x.report('concatenate') { a = ''; 10_000.times { a += 'a' } }
  x.report('interpolate') { a = ''; 10_000.times { a = "#{a}a" } }
end

> ruby count.rb
                  user     system      total        real
append        0.000000   0.000000   0.000000 (  0.003580)
concatenate   0.020000   0.000000   0.020000 (  0.026898)
interpolate   0.020000   0.010000   0.030000 (  0.023168)

One caveat to using the Benchmark.bm method is that, if you are going to use labels, you need to pass the length of the longest label as the argument to this method so that it can get the formatting right.

Using Benchmark.bm in this way is vitally important because benchmark timing numbers, on their own, are not particularly useful. The absolute runtime for any piece of code can depend on a large number of platform and system specific factors. Even running the same benchmark at two different times on the same system can result in significantly different runtimes (for example, if one benchmark is run while another resource heavy process is running in the background). The only way you can draw conclusions from a benchmark is to compare two or more alternatives within the same benchmark run. This is exactly what Benchmark.bm allows us to do.

Play It Again

Sometimes, though, comparing two or more alternatives within the same benchmark is not even enough. Let’s take that last benchmark, for example, and run it using JRuby instead of MRI:

> jruby count.rb
                  user     system      total        real
append        0.290000   0.010000   0.300000 (  0.101000)
concatenate   0.270000   0.010000   0.280000 (  0.059000)
interpolate   0.220000   0.020000   0.240000 (  0.058000)

Running this benchmark with MRI indicated that appending a string using String#<< was significantly faster than using String#+=, but with JRuby it seems that just the opposite is true. While it is not unexpected that the absolute runtimes will be different between JRuby and MRI, it is rather strange to find that the relative ordering of method runtimes should be different. What’s going on here?

To answer that question, we have to introduce the last of the Benchmark library methods that we haven’t explored yet: Benchmark.bmbm. This method, like Benchmark.bm, provides a block variable that you can use to generate reports for different pieces of code, but now each benchmark is run twice. (Also note that we no longer have to pass the label length as an argument.)

require 'benchmark'

Benchmark.bmbm do |x|
  x.report('append')      { a = ''; 10_000.times { a << 'a' } }
  x.report('concatenate') { a = ''; 10_000.times { a += 'a' } }
  x.report('interpolate') { a = ''; 10_000.times { a = "#{a}a" } }
end

> jruby count.rb
Rehearsal -----------------------------------------------
append        0.360000   0.020000   0.380000 (  0.113000)
concatenate   0.280000   0.020000   0.300000 (  0.065000)
interpolate   0.290000   0.020000   0.310000 (  0.064000)
-------------------------------------- total: 0.990000sec

                  user     system      total        real
append        0.050000   0.000000   0.050000 (  0.010000)
concatenate   0.020000   0.010000   0.030000 (  0.018000)
interpolate   0.070000   0.020000   0.090000 (  0.037000)

Wow! What a difference a second run makes! Indeed, the very reason that the Benchmark.bmbm method exists is because it is not uncommon for timing results to differ between the first and second runs of a benchmark. This is because, aside from the code you are hoping to measure, there is usually quite a bit more going on behind the scenes. In the case of JRuby, the longer a program runs the more optimized it becomes. This explains why the first run of our benchmark yields such contradictory results. So, in general, when benchmarking code in Ruby, it is always best to use Benchmark.bmbm.

This is part 2 of 3 in a series of “Prologue” blog posts leading up to a talk I will be giving at RubyConf 2012 in Denver titled “There and Back Again -or- How I Set Out to Benchmark an Algorithm and Ended Up Fixing Ruby”. Check back for the next installment where we will explore how to use the Benchmark library to answer a real-world programming question.