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
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
|
<?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE html
PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
<head>
<title>File: graph.txt</title>
<meta http-equiv="Content-Type" content="text/html; charset=iso-8859-1" />
<meta http-equiv="Content-Script-Type" content="text/javascript" />
<link rel="stylesheet" href="../.././rdoc-style.css" type="text/css" media="screen" />
<script type="text/javascript">
// <![CDATA[
function popupCode( url ) {
window.open(url, "Code", "resizable=yes,scrollbars=yes,toolbar=no,status=no,height=150,width=400")
}
function toggleCode( id ) {
if ( document.getElementById )
elem = document.getElementById( id );
else if ( document.all )
elem = eval( "document.all." + id );
else
return false;
elemStyle = elem.style;
if ( elemStyle.display != "block" ) {
elemStyle.display = "block"
} else {
elemStyle.display = "none"
}
return true;
}
// Make codeblocks hidden by default
document.writeln( "<style type=\"text/css\">div.method-source-code { display: none }</style>" )
// ]]>
</script>
</head>
<body>
<div id="fileHeader">
<h1>graph.txt</h1>
<table class="header-table">
<tr class="top-aligned-row">
<td><strong>Path:</strong></td>
<td>examples/graph.txt
</td>
</tr>
<tr class="top-aligned-row">
<td><strong>Last Update:</strong></td>
<td>Thu Jun 22 15:51:29 Mountain Standard Time 2006</td>
</tr>
</table>
</div>
<!-- banner header -->
<div id="bodyContent">
<div id="contextContent">
<div id="description">
<h1>Graph Profiles</h1>
<p>
Graph profiles show how long each method runs, which methods call it and
which methods it calls.
</p>
<p>
As an example, here is the output from running printers_test.rb:
</p>
<p>
Thread ID: 21277412
</p>
<pre>
%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
</pre>
<h2>Overview</h2>
<p>
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.
</p>
<p>
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).
</p>
<p>
All values are in seconds. For the primary line, the columns represent:
</p>
<pre>
%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.
</pre>
<p>
The interpretation of method names is:
</p>
<ul>
<li>toplevel - The root method that calls all other methods
</li>
<li>MyObject#test - An instance method "test" of the class
"MyObject"
</li>
<li><Object:MyObject>test - The <> characters indicate a singleton
method on a singleton class.
</li>
</ul>
<p>
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.
</p>
<h2>Parents</h2>
<p>
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.
</p>
<p>
For parent lines, the columns represent:
</p>
<pre>
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
</pre>
<p>
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.
</p>
<h2>Children</h2>
<p>
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.
</p>
<p>
For children lines, the columns represent:
</p>
<pre>
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.
</pre>
<p>
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.
</p>
</div>
</div>
</div>
<!-- if includes -->
<div id="section">
<!-- if method_list -->
</div>
<div id="validator-badges">
<p><small><a href="http://validator.w3.org/check/referer">[Validate]</a></small></p>
</div>
</body>
</html>
|
