graph.txt

examples/graph.txt
Last Update: 2010-04-11 23:42:29 -0600

Graph Profiles

Graph profiles show how long each method runs, which methods call it and which methods it calls.

As an example, here is the output from running printers_test.rb:

Thread ID: 21277412

 %total   %self     total      self    children               calls   Name
--------------------------------------------------------------------------------
100.00%   0.00%      8.77      0.00      8.77                   1     #toplevel
                     8.77      0.00      8.77                 1/1     Object#run_primes
--------------------------------------------------------------------------------
                     8.77      0.00      8.77                 1/1     #toplevel
100.00%   0.00%      8.77      0.00      8.77                   1     Object#run_primes
                     0.02      0.00      0.02                 1/1     Object#make_random_array
                     2.09      0.00      2.09                 1/1     Object#find_largest
                     6.66      0.00      6.66                 1/1     Object#find_primes
--------------------------------------------------------------------------------
                     6.63      4.06      2.56             500/501     Object#is_prime
                     2.09      0.00      2.09               1/501     Object#find_largest
 99.48%  46.34%      8.72      4.06      4.66                 501     Integer#upto
                     0.00      0.00      0.00               61/61     Array#[]
                     0.00      0.00      0.00               61/61     Fixnum#>
                     2.09      2.09      0.00               61/61     Kernel.sleep
                     1.24      1.24      0.00       250862/250862     Fixnum#==
                     1.33      1.33      0.00       250862/250862     Fixnum#%
--------------------------------------------------------------------------------
                     6.66      0.01      6.64                 1/1     Object#find_primes
 75.93%   0.17%      6.66      0.01      6.64                   1     Array#select
                     6.64      0.01      6.63             500/500     Object#is_prime
--------------------------------------------------------------------------------
                     6.66      0.00      6.66                 1/1     Object#run_primes
 75.93%   0.00%      6.66      0.00      6.66                   1     Object#find_primes
                     6.66      0.01      6.64                 1/1     Array#select
--------------------------------------------------------------------------------
                     6.64      0.01      6.63             500/500     Array#select
 75.76%   0.17%      6.64      0.01      6.63                 500     Object#is_prime
                     0.00      0.00      0.00             500/501     Fixnum#-
                     6.63      4.06      2.56             500/501     Integer#upto
--------------------------------------------------------------------------------
                     2.09      0.00      2.09                 1/1     Object#run_primes
 23.89%   0.00%      2.09      0.00      2.09                   1     Object#find_largest
                     0.00      0.00      0.00               1/501     Fixnum#-
                     2.09      0.00      2.09               1/501     Integer#upto
                     0.00      0.00      0.00                 1/1     Array#first
                     0.00      0.00      0.00                 1/1     Array#length
--------------------------------------------------------------------------------
                     2.09      2.09      0.00               61/61     Integer#upto
 23.89%  23.89%      2.09      2.09      0.00                  61     Kernel.sleep
--------------------------------------------------------------------------------
                     1.33      1.33      0.00       250862/250862     Integer#upto
 15.12%  15.12%      1.33      1.33      0.00              250862     Fixnum#%
--------------------------------------------------------------------------------
                     1.24      1.24      0.00       250862/250862     Integer#upto
 14.13%  14.13%      1.24      1.24      0.00              250862     Fixnum#==
--------------------------------------------------------------------------------
                     0.02      0.00      0.02                 1/1     Object#run_primes
  0.18%   0.00%      0.02      0.00      0.02                   1     Object#make_random_array
                     0.02      0.02      0.00                 1/1     Array#each_index
                     0.00      0.00      0.00                 1/1     Class#new
--------------------------------------------------------------------------------
                     0.02      0.02      0.00                 1/1     Object#make_random_array
  0.18%   0.18%      0.02      0.02      0.00                   1     Array#each_index
                     0.00      0.00      0.00             500/500     Kernel.rand
                     0.00      0.00      0.00             500/500     Array#[]=
--------------------------------------------------------------------------------
                     0.00      0.00      0.00             500/501     Object#is_prime
                     0.00      0.00      0.00               1/501     Object#find_largest
  0.00%   0.00%      0.00      0.00      0.00                 501     Fixnum#-
--------------------------------------------------------------------------------
                     0.00      0.00      0.00                 1/1     Kernel.rand
  0.00%   0.00%      0.00      0.00      0.00                   1     Integer#to_int
--------------------------------------------------------------------------------
                     0.00      0.00      0.00                 1/1     Object#find_largest
  0.00%   0.00%      0.00      0.00      0.00                   1     Array#first
--------------------------------------------------------------------------------
                     0.00      0.00      0.00                 1/1     Class#new
  0.00%   0.00%      0.00      0.00      0.00                   1     Array#initialize
--------------------------------------------------------------------------------
                     0.00      0.00      0.00                 1/1     Object#find_largest
  0.00%   0.00%      0.00      0.00      0.00                   1     Array#length
--------------------------------------------------------------------------------
                     0.00      0.00      0.00                 1/1     Object#make_random_array
  0.00%   0.00%      0.00      0.00      0.00                   1     Class#new
                     0.00      0.00      0.00                 1/1     Array#initialize
--------------------------------------------------------------------------------
                     0.00      0.00      0.00               61/61     Integer#upto
  0.00%   0.00%      0.00      0.00      0.00                  61     Fixnum#>
--------------------------------------------------------------------------------
                     0.00      0.00      0.00               61/61     Integer#upto
  0.00%   0.00%      0.00      0.00      0.00                  61     Array#[]
--------------------------------------------------------------------------------
                     0.00      0.00      0.00             500/500     Array#each_index
  0.00%   0.00%      0.00      0.00      0.00                 500     Array#[]=
--------------------------------------------------------------------------------
                     0.00      0.00      0.00             500/500     Array#each_index
  0.00%   0.00%      0.00      0.00      0.00                 500     Kernel.rand
                     0.00      0.00      0.00                 1/1     Integer#to_int

Overview

Dashed lines divide the report into entries, with one entry per method. Entries are sorted by total time which is the time spent in the method plus its children.

Each entry has a primary line demarked by values in the %total and %self columns. The primary line represents the method being profiled. Lines above it are the methods that called this method (parents) while the lines below it are the methods it called (children).

All values are in seconds. For the primary line, the columns represent:

%total       - The percentage of time spent in this method and its children
%self        - The percentage of time spent in this method
total        - The time spent in this method and its children.
self         - The time spent in this method.
children     - The time spent in this method's children.
calls        - The number of times this method was called.
name         - The name of the method.

The interpretation of method names is:

  • toplevel - The root method that calls all other methods

  • MyObject#test - An instance method "test" of the class "MyObject"

  • <Object:MyObject>test - The <> characters indicate a singleton method on a singleton class.

For example, we see that 99.48% of the time was spent in Integer#upto and its children. Of that time, 4.06 seconds was spent in Integer#upto itself and 4.66 in its children. Overall, Integer#upto was called 501 times.

Parents

In each entry, the lines above the primary line are the methods that called the current method. If the current method is a root method then no parents are shown.

For parent lines, the columns represent:

total        - The time spent in the current method and it children on behalf of the parent method.
self         - The time spent in this method on behalf of the parent method.
children     - The time spent in this method's children on behalf of the parent.
calls        - The number of times the parent method called this child

Looking at Integer#upto again, we see that it was called 500 times from Object#is_prime and 1 time from find_largest. Of the 8.72 total seconds spent in Integer#upto, 6.63 were done for Object#is_prime and 2.09 for Object#find_largest.

Children

In each entry, the lines below the primary line are the methods that the current method called. If the current method is a leaf method then no children are shown.

For children lines, the columns represent:

total        - The time spent in the child, and its children, on behalf of the current method
self         - The time spent in the child on behalf of the current method.
children     - The time spent in the child's children (ie, granchildren) in behalf of the current method
calls        - The number of times the child method was called by the current method.

Taking our example of Integer#upto, we see that it called five other methods - Array#[], Fixnum#>, Kernel.sleep, Fixnum#= and Fixnum#%. Looking at Kernel.sleep, we see that its spent 2.09 seconds working for Integer#upto and its children spent 0 time working for Integer#upto. To see the overall time Kernel.sleep took we would have to look up its entry in the graph table.