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: [email protected] :~/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_): [email protected] :~/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

[email protected]:~/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: [email protected] :~/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

[email protected]:~/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"

[email protected]:~/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