1 == Understanding Performance Tests Outputs ==
3 === Our First Performance Test ===
5 So how do we profile a request.
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.
12 ----------------------------------------------------------------------------
13 [User profiling_tester]$ gcruby tests/performance/homepage.rb
14 ----------------------------------------------------------------------------
16 After the tests runs for a few seconds you should see something like this.
18 ----------------------------------------------------------------------------
19 HomepageTest#test_homepage (19 ms warmup)
24 Finished in 2.207428 seconds.
25 ----------------------------------------------------------------------------
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?
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.
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
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.
43 Below are examples for Flat Files and Graphical Files
47 .Flat File Output Processing Time
48 ============================================================================
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 ============================================================================
72 So what do these columns tell us:
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.
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
87 Methods are sorted based on %self. Hence the ones taking the most time and resources will be at the top.
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.
92 .Flat File Memory Output
93 ============================================================================
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 ============================================================================
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?*
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.
112 ============================================================================
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 ============================================================================
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?.
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]
133 #TODO (Handily the graph file has links both between it many processes and to the files that actually contain them for debugging.
137 ============================================================================
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 ============================================================================
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.
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.
164 It's pointless trying to represent a tree file textually so here's a few pretty pictures of it's usefulness
167 [caption="KCachegrind graph"]
168 image:images/kgraph.png[Graph created by KCachegrind]
171 [caption="KCachegrind List"]
172 image:images/klist.png[List created by KCachegrind]
174 #TODO Add a bit more information to this.
176 == Getting to the Point of all of this ==
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