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
|
= 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.
|
