The Need for Speed: Ruby Profiler & Benchmarking (Part 2)

In my last blog post, I showed how you can estimate the processing time of your algorithm with Big-O notation. But there are easier, more concrete ways to determine how long it will take your algorithms to run. Ruby has two great tools that will help you determine bottlenecks in your code and help you decide which algorthms are the most efficient: Ruby Profiler & Benchmark Modules

Ruby Profiler
Profiling your program is a way of determining how long each method takes to execute compared to each other. This allows you to detect which of your methods are bottlenecks, or which methods are taking the majority of the processing time. You might then be able to choose a more efficient method.

How it works: Run your ruby program typing -rprofile before the script name, like so:
$ ruby -rprofile example.rb

Your script will run and then be followed by a table. Each method called in the program is listed in the table on the right-hand side. The total percentage of the time spent in the methods is on the left. The table is ordered by total percentage, so the most time-consuming methods are on the top.

It’s important to note that profiling your program will slow down the actual execution time of your program, so you should only activate it when you need it. Benchmarking (coming up next) is better at determining the actual execution time. Profiling just allows us to see which methods are comparatively faster than other methods.

Example of Ruby Profiling
I compared two different strategies of searching for a word in a dictionary, first with a For Loop and second with an Until Loop. Here’s the code:

...
#Search for the word happy in a dictionary of 10,000 words
wordlist = build_dictionary(10000, "dictionary.txt")
word_to_find = "HAPPY"

#This is the For Loop which is results in #nil in the output table
counter = 0
word_index = 0
for word in wordlist
	if word == word_to_find
		word_index = counter
	end
	counter += 1
end

#This is the Until Loop which is results in Fixnum#+ in the output table
counter = 0
word_index = 0
until word_index > 0
	if wordlist[counter] == word_to_find
		word_index = counter
	end
	counter += 1
end

And here’s the table output:

    %   cumulative   self              self     total
  time   seconds   seconds    calls  ms/call  ms/call  name
 30.18     0.51      0.51    10002     0.05     0.24  Object#build_dictionary
 15.98     0.78      0.27    10000     0.03     0.03  nil#
  8.28     0.92      0.14        1   140.00   840.00  IO#each_line
  5.92     1.02      0.10        1   100.00   400.00  Array#each
  4.73     1.10      0.08    18273     0.00     0.00  Array#[]
  4.14     1.17      0.07    10000     0.01     0.01  String#split
  2.96     1.22      0.05    18273     0.00     0.00  String#==
  2.96     1.27      0.05    28273     0.00     0.00  Fixnum#+
  2.37     1.31      0.04     8274     0.00     0.00  Fixnum#>
  2.37     1.35      0.04    10000     0.00     0.00  Fixnum#==
  1.18     1.37      0.02    10000     0.00     0.00  Array#<<
  0.00     1.37      0.00        1     0.00     0.00  TracePoint#enable
  0.00     1.37      0.00        1     0.00     0.00  Module#method_added
  0.00     1.37      0.00        2     0.00     0.00  IO#set_encoding
  0.00     1.37      0.00        1     0.00     0.00  File#initialize
  0.00     1.37      0.00        1     0.00     0.00  MonitorMixin#mon_exit
  0.00     1.37      0.00        1     0.00     0.00  Mutex#unlock
  0.00     1.37      0.00        1     0.00     0.00  IO#close
  0.00     1.37      0.00        1     0.00   840.00  IO.open
  0.00     1.37      0.00        1     0.00     0.00  MonitorMixin#mon_check_owner
  0.00     1.37      0.00        1     0.00     0.00  MonitorMixin#mon_enter
  0.00     1.37      0.00        1     0.00     0.00  Mutex#lock
  0.00     1.37      0.00        2     0.00     0.00  Fixnum#to_s
  0.00     1.37      0.00        4     0.00     0.00  IO#write
  0.00     1.37      0.00        2     0.00     0.00  IO#puts
  0.00     1.37      0.00        2     0.00     0.00  Kernel#puts
  0.00     1.37      0.00        3     0.00     0.00  Thread.current
  0.00     1.37      0.00        1     0.00     0.00  TracePoint#disable
  0.00     1.69      0.00        1     0.00  1690.00  #toplevel

It became obvious pretty quickly that the For Loop method (represented on the table by #nil) takes up a larger percentage of the execution time than the Until Loop (represented on the table by Fixnum#+) or close to 16%.

I don’t know about you, but I think this table is pretty confusing. There’s another way to figure out which code is faster…

Benchmarking
Benchmarking is a good way to check the execution time of part of your code in Ruby. Using the Ruby Benchmark library, we can add a little bit of code to our algorithms to track the processing time and get a user friendly output table.

Using the same example as above here is my code:

 require 'benchmark'

wordlist = build_dictionary(150000, "dictionary.txt")
word_to_find = "RIDICULOUSLY"

Benchmark.bm do |b|
	b.report("For Loop: ") do
		counter = 0
		word_index = 0
		for word in wordlist
			if word == word_to_find
				word_index = counter
			end
			counter += 1
		end
	end	
	b.report("Until Loop: ") do
		counter = 0
		word_index = 0
		until word_index > 0
			if wordlist[counter] == word_to_find
				word_index = counter
			end
			counter += 1
		end
	end
end

And here is the output table:

                user     system      total        real
For Loop:     0.030000   0.000000   0.030000 (  0.024913)
Until Loop:   0.010000   0.000000   0.010000 (  0.015930)

It’s pretty clear that the For Loop takes nearly twice as long as the Until Loop in real seconds.

While Ruby Profiler is super simple to use (just type -rprofile in the command line), I find Benchmark much easier to comprehend. They are both helpful though. If you don’t know where your bottlenecks are, use profiling. And if you know what you want to track, I’d use Benchmark.

Leave a Reply

Your email address will not be published. Required fields are marked *