Share this:

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.

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:

alan@alan-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 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):

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

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:

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

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 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.

Image by monkeyc.net

  • Pingback: Webs Developer » Why I Love Reading Other People’s Code And You Should Too()

  • Pingback: obliczanie układu równań liniowych, mierzenie wydajności ruby | dg6.pl()

  • Pingback: Webs Developer » Ruby Procs And Lambdas (And The Difference Between Them)()

  • Pingback: Thinking In Rails » Blog Archive » Optimizing Everything To Instant*()

  • Pingback: Using benchmark to time rails code « RailsWays()

  • http://batkins.net Ben

    Thanks for the article. Learned a lot about Benchmark reading this, but just so you know, your last example is the most convenient, but your calculation is incorrect. If you call Benchmark.realtime, the result is returned in seconds, not microseconds.

    So instead of putting this after the Benchmark.realtime do block: puts “Time elapsed #{time*1000} milliseconds”

    You can simply put this:
    puts “Time elapsed #{time} seconds”
    Or if you need milliseconds, you can do this:
    puts “Time elapsed #{time/1000} milliseconds”

    Reference: http://snippets.aktagon.com/snippets/81-How-to-benchmark-your-Ruby-code

    Also if you read the docs for the Benchmark module, it clearly states: “The unit of time is seconds.”

    • SrslyWTF

      Are you retarded? If 5 seconds is returned by the method, then that would be 5000 milliseconds. Therefore he’s right. You multiply seconds by 1000 to get the number of milliseconds. Duh.

      • Matt

        Unnecessarily harsh. It’s within your grasp to correct someone without sounding like an asshole.

    • Jumpseller

      normally use:

      time = Benchmark.realtime do
      (1..10000).each { |i| i }
      end
      puts “Time elapsed #{time} seconds”

      because 0.2 or 0.02 seconds it’s easier to understand for me then milisecs.

  • Lorenzo

    Or you can use the rubyperf gem, that is based on benchmark and gives you a bunch of extras.

  • Matías Insaurralde

    Really useful

  • http://cureforblur.com/ David Hestrin

    What if I want some code to be executed if the user doesn’t input data by a certain point?

    I want to do a math game where it asks people to answer a math problem and then if they don’t answer in 10 seconds it will say “Too slow!”

    Thanks for the article.

  • http://tecnomorfose.blogspot.com Wellington Torrejais

    Thanks!