Timing Ruby Code – It Is Easy With Benchmark

beginning_time = Time.now
(1..10000).each { |i| i }
end_time = Time.now
puts "Time elapsed #{(end_time - beginning_time)*1000} milliseconds"

You get the current time before and the current time after the code you need to measure the running time of and you simply subtract them from each other (to get the time in seconds). The output is as follows:

justin@justin-ubuntu-vm:~/projects$ ruby time.rb
Time elapsed 4.049 milliseconds

But this seemed rather inflexible, and you wouldn't want to have to do it over and over again, so I rolled it into a method, to allow myself to time the execution of other methods, like so.

def time_method(method, *args)
  beginning_time = Time.now
  self.send(method, args)
  end_time = Time.now
  puts "Time elapsed #{(end_time - beginning_time)*1000} milliseconds"
end
 
def method_to_time(*args)
  (1..10000).each { |i| i }
end
 
time_method(:method_to_time)

As you can see we can now pass a symbol version of the method name we want to time into ourtime_method. Inside the time_method we will call "send" on the current object passing in the method name (which will essentially call the method we want to time) and will wrap this call in our timing code, producing similar output (to that from above):

justin@justin-ubuntu-vm:~/projects$ ruby time.rb
Time elapsed 6.198 milliseconds

This is somewhat better, but now we can only time methods, not arbitrary code which is not very nice. So, we enhance our time_method by allowing it to take a block.

def time_method(method=nil, *args)
  beginning_time = Time.now
  if block_given?
    yield
  else
    self.send(method, args)
  end
  end_time = Time.now
  puts "Time elapsed #{(end_time - beginning_time)*1000} milliseconds"
end
 
time_method do
  (1..10000).each { |i| i }
end

justin@justin-ubuntu-vm:~/projects$ ruby time.rb
Time elapsed 6.198 milliseconds

This allows us to time arbitrary code as well as methods – awesome!

However as I was browsing some code the other day (for unrelated reasons), I discovered that it wasn't so awesome, because I reinvented the wheel and the existing wheel is potentially better.

If enjoy my Ruby posts (like this one), here is some of the Ruby related stuff I am planning to write about in the near future.

• Passing methods as arguments in Ruby
• Ruby object serialization (and deserialization :))
• A look at serializing Ruby blocks/procs
• plus much more…

Ruby Benchmark Module

Ruby already has a module as part of its standard libraries that basically does all that timing stuff I was playing with above, it's the Benchmark module. For example:

require "benchmark"
 
time = Benchmark.measure do
  (1..10000).each { |i| i }
end
puts time

As you can see we pass the block we want to time to Benchmark.measure which will return output that will look like this when printed:

justin@justin-ubuntu-vm:~/projects$ ruby time.rb
  0.010000   0.000000   0.010000 (  0.003298)

You're probably getting the picture already, but if not here is another way to use benchmark which will label our output to make it clearer:

require "benchmark"
 
Benchmark.bm(7) do |x|
  x.report("first:")   { (1..10000).each { |i| i } }
  x.report("second:") { (1..10000).each { |i| i }}
  x.report("third:")  { (1..10000).each { |i| i }}
end

justin@justin-ubuntu-vm:~/projects$ ruby time.rb
             user     system      total        real
first:   0.000000   0.010000   0.010000 (  0.008010)
second:  0.000000   0.000000   0.000000 (  0.005251)
third:   0.000000   0.000000   0.000000 (  0.003678)

Not only did we run and time our code, but we did it multiple times producing, the user, system, totaland real times for each run. You can imagine how useful this could be especially considering that if we use one of the other methods of the Benchmark module (Benchmark.benchmark) it will allow us to format our output as well as easily produce averages and totals for all the runs.

Of course if you don't want all that extraneous stuff printed, the easiest way to use it is:

require "benchmark"
 
time = Benchmark.realtime do
  (1..10000).each { |i| i }
end
puts "Time elapsed #{time*1000} milliseconds"

justin@justin-ubuntu-vm:~/projects$ ruby time.rb
Time elapsed 5.35893440246582 milliseconds

Which simply gives you the real elapsed time in seconds which you can then print out yourself. In hindsight I am still pretty happy with my own time_method way as it is simple, flexible and mine :). But it is good to know that Ruby already provides a facility to easily time execution without having to write any extra code.