blob: fa01d413a1cd58c30640d3e977d037c294f078fc (
plain) (
blame)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
|
== Understanding Performance Tests Outputs ==
=== Our First Performance Test ===
So how do we profile a request.
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.
In the terminal run
[source, ruby]
----------------------------------------------------------------------------
[User profiling_tester]$ gcruby tests/performance/homepage.rb
----------------------------------------------------------------------------
After the tests runs for a few seconds you should see something like this.
----------------------------------------------------------------------------
HomepageTest#test_homepage (19 ms warmup)
process_time: 26 ms
memory: 298.79 KB
objects: 1917
Finished in 2.207428 seconds.
----------------------------------------------------------------------------
Simple but efficient.
* Process Time refers to amount of time necessary to complete the action.
* memory is the amount of information loaded into memory
* object ??? #TODO find a good definition. Is it the amount of objects put into a ruby heap for this process?
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.
*The Three types are*
* Flat File - A simple text file with the data laid out in a grid
* 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.
* Tree File - A file output that can be use in conjunction with KCachegrind to visualize the process
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.
Below are examples for Flat Files and Graphical Files
=== Flat Files ===
.Flat File Output Processing Time
============================================================================
Thread ID: 2279160
Total: 0.026097
%self total self wait child calls name
6.41 0.06 0.04 0.00 0.02 571 Kernel#===
3.17 0.00 0.00 0.00 0.00 172 Hash#[]
2.42 0.00 0.00 0.00 0.00 13 MonitorMixin#mon_exit
2.05 0.00 0.00 0.00 0.00 15 Array#each
1.56 0.00 0.00 0.00 0.00 6 Logger#add
1.55 0.00 0.00 0.00 0.00 13 MonitorMixin#mon_enter
1.36 0.03 0.00 0.00 0.03 1 ActionController::Integration::Session#process
1.31 0.00 0.00 0.00 0.00 13 MonitorMixin#mon_release
1.15 0.00 0.00 0.00 0.00 8 MonitorMixin#synchronize-1
1.09 0.00 0.00 0.00 0.00 23 Class#new
1.03 0.01 0.00 0.00 0.01 5 MonitorMixin#synchronize
0.89 0.00 0.00 0.00 0.00 74 Hash#default
0.89 0.00 0.00 0.00 0.00 6 Hodel3000CompliantLogger#format_message
0.80 0.00 0.00 0.00 0.00 9 c
0.80 0.00 0.00 0.00 0.00 11 ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
0.79 0.01 0.00 0.00 0.01 1 ActionController::Benchmarking#perform_action_without_rescue
0.18 0.00 0.00 0.00 0.00 17 <Class::Object>#allocate
============================================================================
So what do these columns tell us:
* %self - The percentage of time spent processing the method. This is derived from self_time/total_time
* total - The time spent in this method and its children.
* self - The time spent in this method.
* wait - Time processed was queued
* child - The time spent in this method's children.
* calls - The number of times this method was called.
* name - The name of the method.
Name can be displayed three seperate ways:
* #toplevel - The root method that calls all other methods
* MyObject#method - Example Hash#each, The class Hash is calling the method each
* <Object:MyObject>#test - The <> characters indicate a singleton method on a singleton class. Example <Class::Object>#allocate
Methods are sorted based on %self. Hence the ones taking the most time and resources will be at the top.
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.
.Flat File Memory Output
============================================================================
Thread ID: 2279160
Total: 509.724609
%self total self wait child calls name
4.62 23.57 23.57 0.00 0.00 34 String#split
3.95 57.66 20.13 0.00 37.53 3 <Module::YAML>#quick_emit
2.82 23.70 14.35 0.00 9.34 2 <Module::YAML>#quick_emit-1
1.37 35.87 6.96 0.00 28.91 1 ActionView::Helpers::FormTagHelper#form_tag
1.35 7.69 6.88 0.00 0.81 1 ActionController::HttpAuthentication::Basic::ControllerMethods#authenticate_with_http_basic
1.06 6.09 5.42 0.00 0.67 90 String#gsub
1.01 5.13 5.13 0.00 0.00 27 Array#-
============================================================================
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?*
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.
.Flat File Objects
============================================================================
Thread ID: 2279160
Total: 6537.000000
%self total self wait child calls name
15.16 1096.00 991.00 0.00 105.00 66 Hash#each
5.25 343.00 343.00 0.00 0.00 4 Mysql::Result#each_hash
4.74 2203.00 310.00 0.00 1893.00 42 Array#each
3.75 4529.00 245.00 0.00 4284.00 1 ActionView::Base::CompiledTemplates#_run_erb_47app47views47layouts47application46html46erb
2.00 136.00 131.00 0.00 5.00 90 String#gsub
1.73 113.00 113.00 0.00 0.00 34 String#split
1.44 111.00 94.00 0.00 17.00 31 Array#each-1
============================================================================
#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?.
=== Graph Files ===
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]
#TODO (Handily the graph file has links both between it many processes and to the files that actually contain them for debugging.
)
.Graph File
============================================================================
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
/____________________________________________________________________________/
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/501 Array#[]=
/____________________________________________________________________________/
============================================================================
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.
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.
=== Tree Files ===
It's pointless trying to represent a tree file textually so here's a few pretty pictures of it's usefulness
.KCachegrind Graph
[caption="KCachegrind graph"]
image:images/kgraph.png[Graph created by KCachegrind]
.KCachegrind List
[caption="KCachegrind List"]
image:images/klist.png[List created by KCachegrind]
#TODO Add a bit more information to this.
== Getting to the Point of all of this ==
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
|
