1. Technology
You can opt-out at any time. Please refer to our privacy policy for contact information.

Running the Ruby Profiler

Looking at Your Methods


Running the Ruby Profiler

Profiling your Ruby program is a way of determining which methods are called and how long each method takes to complete. It's an important step in determining where your bottlenecks are so you can concentrate on the big time sinks when optimizing your code. If one method is taking 70% of the total program execution time, making this one method faster will do a lot more than improving the efficiency of several methods that only take 20% of the time.

Profiling is Not Benchmarking

Though related, profiling cannot be used as a benchmarking program. The profiling library itself slows the program down considerably, making it difficult to accurately benchmark the code. Though it may seem to be a counterintuitive mechanism used to measure the time it takes to execute a program, since it slows the program down uniformly, it's not. No matter how much the program is slowed down, the percentages should always be the same, and that's the important part.

It's as Easy as -rprofile

To run the Ruby profiler on any of your programs, simply require the profile library. This can be done either from the Ruby program itself, or from the command-line. The command-line method is preferred as it doesn't require making any modifications to your program. Simply run your program with the ruby command, adding -rprofile before your script name.

The following example program reads a list of words from a file, finds a word in the file and prints the word as well as the 5 words in either direction. It's run through the profiler and the output is shown.

 #!/usr/bin/env ruby
 words = []
 File.open(ARGV[0], 'r') do|file|
   file.each do|w|
     words << w.chomp.downcase
 idx = words.index(ARGV[1])
 words[idx] = "* #{words[idx]}"
 puts words[ ((idx - 5) .. (idx + 5)) ]
 $ ruby -rprofile 1.rb words ruby
 * ruby
   % cumulative self self total
  time seconds seconds calls ms/call ms/call name
  61.27 8.21 8.21 1 8210.00 12850.00 IO#each
  13.58 10.03 1.82 98569 0.02 0.02 String#downcase
  11.04 11.51 1.48 98569 0.02 0.02 String#chomp
  10.00 12.85 1.34 98569 0.01 0.01 Array#<<
   2.69 13.21 0.36 1 360.00 550.00 Array#index
   1.42 13.40 0.19 14387 0.01 0.01 String#==
   0.00 13.40 0.00 1 0.00 12850.00 IO#open
   0.00 13.40 0.00 22 0.00 0.00 IO#write
   0.00 13.40 0.00 4 0.00 0.00 Array#[]
   0.00 13.40 0.00 1 0.00 0.00 IO#close
   0.00 13.40 0.00 1 0.00 0.00 Array#[]=
   0.00 13.40 0.00 1 0.00 0.00 Kernel.puts
   0.00 13.40 0.00 1 0.00 0.00 Fixnum#+
   0.00 13.40 0.00 1 0.00 0.00 Fixnum#-
   0.00 13.40 0.00 11 0.00 0.00 Fixnum#==
   0.00 13.40 0.00 1 0.00 0.00 File#initialize
   0.00 13.40 0.00 1 0.00 13400.00 #toplevel

The Output Table

Each method called in the program is represented in the table. The method names are on the right and 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.

As you can see, the IO#each method is taking most of the time. This is from reading the file one line at a time. Since this method takes the longest, it could be sped up and made more efficient. Making this method more efficient will have the greatest impact on overall efficiency of the program. One possible way to speed up the IO#each method is the to read the entire file into a buffer and use String#split, thereby reducing the total number of IO calls made by the operating systems and more efficiently utilizing the operating system and hard drive's cache systems.

  1. About.com
  2. Technology
  3. Ruby
  4. Advanced Ruby
  5. Running the Ruby Profiler

©2014 About.com. All rights reserved.