Timing Ruby Code – It Is Easy With Benchmark

Recently I needed to time some Ruby code as it was running (related to my post on list intersection and another post on skip pointers which I haven’t finished writing yet). Being a bit too keen (as I often am :)) and seeing as it would be fairly easy to do, I decided to quickly roll an implementation similar to the following.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48


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:

<pre>alan@alan-ubuntu-vm:~/projects$ ruby time.rb
Time elapsed 4.049 milliseconds</pre>

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.

```ruby
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 our _time_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_):

<pre>alan@alan-ubuntu-vm:~/projects$ ruby time.rb
Time elapsed 6.198 milliseconds</pre>

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.

```ruby
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

alan@alan-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…

Be sure to subscribe to my feed if you don’t want to miss it.

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:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22


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:

<pre>alan@alan-ubuntu-vm:~/projects$ ruby time.rb
  0.010000   0.000000   0.010000 (  0.003298)</pre>

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:

```ruby
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

alan@alan-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, total and 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:

1
2
3
4
5
6


require "benchmark"

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

alan@alan-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 _timemethod 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.

Image by monkeyc.net

Table of Contents

Ruby Benchmark Module