vendor/rails/railties/doc/guides/source/benchmarking_and_profiling/rubyprof.txt

   1 == Understanding Performance Tests Outputs ==
   2
   3 === Our First Performance Test ===
   4
   5 So how do we profile a request.
   6
   7 One of the things that is important to us is how long it takes to render the home page - so let's make a request to the home page. Once the request is complete, the results will be outputted in the terminal.
   8
   9 In the terminal run
  10
  11 [source, ruby]
  12 ----------------------------------------------------------------------------
  13 [User profiling_tester]$ gcruby tests/performance/homepage.rb
  14 ----------------------------------------------------------------------------
  15
  16 After the tests runs for a few seconds you should see something like this.
  17
  18 ----------------------------------------------------------------------------
  19 HomepageTest#test_homepage (19 ms warmup)
  20         process_time: 26 ms
  21               memory: 298.79 KB
  22              objects: 1917
  23
  24 Finished in 2.207428 seconds.
  25 ----------------------------------------------------------------------------
  26
  27 Simple but efficient.
  28
  29 * Process Time refers to amount of time necessary to complete the action.
  30 * memory is the amount of information loaded into memory
  31 * object ??? #TODO find a good definition. Is it the amount of objects put into a ruby heap for this process?
  32
  33 In addition we also gain three types of itemized log files for each of these outputs. They can be found in your tmp directory of your application.
  34
  35 *The Three types are*
  36
  37 * Flat File - A simple text file with the data laid out in a grid
  38 * Graphical File - A html colored coded version of the simple text file with hyperlinks between the various methods. Most useful is the bolding of the main processes for each portion of the action.
  39 * Tree File - A file output that can be use in conjunction with KCachegrind to visualize the process
  40
  41 NOTE: KCachegrind is Linux only. For Mac this means you have to do a full KDE install to have it working in your OS. Which is over 3 gigs in size. For windows there is clone called wincachegrind but it is no longer actively being developed.
  42
  43 Below are examples for Flat Files and Graphical Files
  44
  45 === Flat Files ===
  46
  47 .Flat File Output Processing Time
  48 ============================================================================
  49 Thread ID: 2279160
  50 Total: 0.026097
  51
  52  %self     total     self     wait    child    calls  name
  53   6.41      0.06     0.04     0.00     0.02      571  Kernel#===
  54   3.17      0.00     0.00     0.00     0.00      172  Hash#[]
  55   2.42      0.00     0.00     0.00     0.00       13  MonitorMixin#mon_exit
  56   2.05      0.00     0.00     0.00     0.00       15  Array#each
  57   1.56      0.00     0.00     0.00     0.00        6  Logger#add
  58   1.55      0.00     0.00     0.00     0.00       13  MonitorMixin#mon_enter
  59   1.36      0.03     0.00     0.00     0.03        1  ActionController::Integration::Session#process
  60   1.31      0.00     0.00     0.00     0.00       13  MonitorMixin#mon_release
  61   1.15      0.00     0.00     0.00     0.00        8  MonitorMixin#synchronize-1
  62   1.09      0.00     0.00     0.00     0.00       23  Class#new
  63   1.03      0.01     0.00     0.00     0.01        5  MonitorMixin#synchronize
  64   0.89      0.00     0.00     0.00     0.00       74  Hash#default
  65   0.89      0.00     0.00     0.00     0.00        6  Hodel3000CompliantLogger#format_message
  66   0.80      0.00     0.00     0.00     0.00        9  c
  67   0.80      0.00     0.00     0.00     0.00       11  ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
  68   0.79      0.01     0.00     0.00     0.01        1  ActionController::Benchmarking#perform_action_without_rescue
  69   0.18      0.00     0.00     0.00     0.00       17  <Class::Object>#allocate
  70 ============================================================================
  71
  72 So what do these columns tell us:
  73
  74         * %self - The percentage of time spent processing the method. This is derived from self_time/total_time
  75         * total - The time spent in this method and its children.
  76         * self - The time spent in this method.
  77         * wait - Time processed was queued
  78         * child - The time spent in this method's children.
  79         * calls - The number of times this method was called.
  80     *  name - The name of the method.
  81
  82 Name can be displayed three seperate ways:
  83         * #toplevel - The root method that calls all other methods
  84         * MyObject#method - Example Hash#each, The class Hash is calling the method each
  85         * <Object:MyObject>#test - The <> characters indicate a singleton method on a singleton class. Example <Class::Object>#allocate
  86
  87 Methods are sorted based on %self. Hence the ones taking the most time and resources will be at the top.
  88
  89 So for Array#each which is calling each on the class array. We find that it processing time is 2% of the total and was called 15 times. The rest of the information is 0.00 because the process is so fast it isn't recording times less then 100 ms.
  90
  91
  92 .Flat File Memory Output
  93 ============================================================================
  94 Thread ID: 2279160
  95 Total: 509.724609
  96
  97  %self     total     self     wait    child    calls  name
  98   4.62     23.57    23.57     0.00     0.00       34  String#split
  99   3.95     57.66    20.13     0.00    37.53        3  <Module::YAML>#quick_emit
 100   2.82     23.70    14.35     0.00     9.34        2  <Module::YAML>#quick_emit-1
 101   1.37     35.87     6.96     0.00    28.91        1  ActionView::Helpers::FormTagHelper#form_tag
 102   1.35      7.69     6.88     0.00     0.81        1  ActionController::HttpAuthentication::Basic::ControllerMethods#authenticate_with_http_basic
 103   1.06      6.09     5.42     0.00     0.67       90  String#gsub
 104   1.01      5.13     5.13     0.00     0.00       27  Array#-
 105 ============================================================================
 106
 107 Very similar to the processing time format. The main difference here is that instead of calculating time we are now concerned with the amount of KB put into memory *(or is it strictly into the heap) can I get clarification on this minor point?*
 108
 109 So for <Module::YAML>#quick_emit which is  singleton method on the class YAML it uses 57.66 KB in total, 23.57 through its own actions, 6.69 from actions it calls itself and that it was called twice.
 110
 111 .Flat File Objects
 112 ============================================================================
 113 Thread ID: 2279160
 114 Total: 6537.000000
 115
 116  %self     total     self     wait    child    calls  name
 117  15.16   1096.00   991.00     0.00   105.00       66  Hash#each
 118   5.25    343.00   343.00     0.00     0.00        4  Mysql::Result#each_hash
 119   4.74   2203.00   310.00     0.00  1893.00       42  Array#each
 120   3.75   4529.00   245.00     0.00  4284.00        1  ActionView::Base::CompiledTemplates#_run_erb_47app47views47layouts47application46html46erb
 121   2.00    136.00   131.00     0.00     5.00       90  String#gsub
 122   1.73    113.00   113.00     0.00     0.00       34  String#split
 123   1.44    111.00    94.00     0.00    17.00       31  Array#each-1
 124 ============================================================================
 125
 126
 127  #TODO Find correct terminology for how to describe what this is exactly profiling as in are there really 2203 array objects or 2203 pointers to array objects?.
 128
 129 === Graph Files ===
 130
 131 While the information gleamed from flat files is very useful we still don't know which processes each method is calling. We only know how many. This is not true for a graph file. Below is a text representation of a graph file. The actual graph file is an html entity and an example of which can be found link:examples/graph.html[Here]
 132
 133 #TODO (Handily the graph file has links both between it many processes and to the files that actually contain them for debugging.
 134  )
 135
 136 .Graph File
 137 ============================================================================
 138 Thread ID: 21277412
 139
 140   %total   %self     total      self    children               calls   Name
 141 /____________________________________________________________________________/
 142 100.00%   0.00%      8.77      0.00      8.77                   1     #toplevel*
 143                      8.77      0.00      8.77                 1/1     Object#run_primes
 144 /____________________________________________________________________________/
 145                      8.77      0.00      8.77                 1/1     #toplevel
 146 100.00%   0.00%      8.77      0.00      8.77                   1     Object#run_primes*
 147                      0.02      0.00      0.02                 1/1     Object#make_random_array
 148                      2.09      0.00      2.09                 1/1     Object#find_largest
 149                      6.66      0.00      6.66                 1/1     Object#find_primes
 150 /____________________________________________________________________________/
 151                      0.02      0.02      0.00                 1/1     Object#make_random_array
 152 0.18%     0.18%      0.02      0.02      0.00                   1     Array#each_index
 153                      0.00      0.00      0.00             500/500     Kernel.rand
 154                      0.00      0.00      0.00             500/501     Array#[]=
 155 /____________________________________________________________________________/
 156 ============================================================================
 157
 158 As you can see the calls have been separated into slices, no longer is the order determined by process time but instead from hierarchy. Each slice profiles a primary entry, with the primary entry's parents being shown above itself and it's children found below. A primary entry can be ascertained by it having values in the %total and %self columns. Here the main entry here have been bolded for connivence.
 159
 160 So if we look at the last slice. The primary entry would be Array#each_index. It takes 0.18% of the total process time and it is only called once. It is called from Object#make_random_array which is only called once. It's children are Kernal.rand which is called by it all 500 its times that it was call in this action and Arry#[]= which was called 500 times by Array#each_index and once by some other entry.
 161
 162 === Tree Files ===
 163
 164 It's pointless trying to represent a tree file textually so here's a few pretty pictures of it's usefulness
 165
 166 .KCachegrind Graph
 167 [caption="KCachegrind graph"]
 168 image:images/kgraph.png[Graph created by KCachegrind]
 169
 170 .KCachegrind List
 171 [caption="KCachegrind List"]
 172 image:images/klist.png[List created by KCachegrind]
 173
 174 #TODO Add a bit more information to this.
 175
 176 == Getting to the Point of all of this ==
 177
 178 Now I know all of this is a bit dry and academic. But it's a very powerful tool when you know how to leverage it properly. Which we are going to take a look at in our next section
 179