ruby-prof and call graphs

Sorry it's been so long since my last post. I've been on vacation for the last week, and Internet access wasn't a big part of it. I did get a bit of writing done for my book though (one of the perks of insomnia). I promised some more info about ruby-prof, so here it is.

The biggest difference between Profile and ruby-prof is the ability to generate call graphs. A call graph shows not only individual methods and their profiling data, but also the parent and child method calls associated with them. Call graphs can be generated in plain text or html. Unless you need the plain text, the html report is a better choice as it is easier to read and has some cross referencing features built into it.

ruby-prof has an optional -p flag that takes one of three options: flat,which generates a normal profiling report; graph, which generates a plain test call graph report; and graph_html, whichgenerates an html call graph report. Since call graphs are a bit less common than normal profiling data, here's a sample that we can walk through to get a better feel for what can do for you. I generated it like this: ruby-prof -p graph call_rotator test_file. (I'm also trimming the output to show just the top several methods, this report was 146 lines long.)

Thread ID: 537836452
  %total   %self total  self  children        calls Name
---------------------------------------------------------------
                  0.00  0.00    0.00            1/1   <Class::Time>#now
   0.00%   0.00%  0.00  0.00    0.00              1   Time#initialize
---------------------------------------------------------------
                  0.00  0.00    0.00    10011/10011   Comparable#>
   0.00%   0.00%  0.00  0.00    0.00          10011   Time#<=>
---------------------------------------------------------------
                  0.09  0.09    0.00    10011/10011   CallRot#read_line
  28.12%  28.12%  0.09  0.09    0.00          10011   String#split
---------------------------------------------------------------
                  0.00  0.00    0.00          12/12   Array#each
   0.00%   0.00%  0.00  0.00    0.00             12   String#gsub!
---------------------------------------------------------------
                  0.01  0.01    0.00    10011/10011   Class#new
   3.12%   3.12%  0.01  0.01    0.00          10011   OnCall#initialize
---------------------------------------------------------------
                  0.00  0.00    0.00            1/1   Class#new
   0.00%   0.00%  0.00  0.00    0.00              1   Object#initialize
---------------------------------------------------------------
                  0.00  0.00    0.00            3/6   Kernel#require__
                  0.00  0.00    0.00            3/6   Module#attr_reader
   0.00%   0.00%  0.00  0.00    0.00              6   Module#method_added
---------------------------------------------------------------
                  0.00  0.00    0.00            1/1   Kernel#require__
   0.00%   0.00%  0.00  0.00    0.00              1   Module#attr_reader
                  0.00  0.00    0.00            3/6   Module#method_added
---------------------------------------------------------------
                  0.00  0.00    0.00            1/1   Kernel#require
   0.00%   0.00%  0.00  0.00    0.00              1   Kernel#require__
                  0.00  0.00    0.00            3/6   Module#method_added
                  0.00  0.00    0.00            1/1   Module#attr_reader
                  0.00  0.00    0.00            3/3   Class#inherited
---------------------------------------------------------------
                  0.00  0.00    0.00            1/1   Kernel#load
   0.00%   0.00%  0.00  0.00    0.00              1   Kernel#require
                  0.00  0.00    0.00            1/1   Kernel#require__
---------------------------------------------------------------

The first interesting chunk of the report is the third block down. It has two lines, the top line is the calling method, the second line is the method being called. In the call graph reports, the line showing %total and %self values is the method being reported, everything above it is a calling method and everything below it is a method being called. This report shows that String#split takes up a bit over 28% of the programs running time. It is called 10011 times, all of them by CallRot#ReadLine.

A bit further down, is the chunk about Module#method_added. In this case there are two calling methods. Each calls Module#method_added three times, for a total of six calls. This is shown in the calls field, 3/6 in both cases.

Two blocks further down, you can see the report for Kernel#require__, this has one calling and three called methods. Each of the called methods also shows the number of calls made by Kernel#require__ and the total number of calls made.

Every method (calling, called, or reported) is shown with some profiling data: total, self, and children. These fields show the amount of time spent there. Because my profiling run was fairly short, there's not a lot of data to work with. If this were a program that took hours to run, we'd be able to use this information (along with the number of calls made) to identify where we really need to focus our optimization efforts.

There's one more feature of ruby-prof (and Profile for that matter) that I'd still like to cover — controlling what parts of your program are profiled. I'll look at that in another post though. Hopefully this is enough to chew on for one day.

If you found this post helpful, you might want to look at my ruby-prof post collection.