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
|
= 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:
Measure Mode: wall_time
Thread ID: 70310439543100
Fiber ID: 70310456289620
Total Time: 0.05264616012573242
Sort by: total_time
%total %self total self wait child calls name
--------------------------------------------------------------------------------
100.00% 0.01% 0.053 0.000 0.000 0.053 1 PrintersTest#setup
0.053 0.000 0.000 0.053 1/1 Object#run_primes
--------------------------------------------------------------------------------
0.053 0.000 0.000 0.053 1/1 PrintersTest#setup
99.99% 0.01% 0.053 0.000 0.000 0.053 1 Object#run_primes
0.052 0.000 0.000 0.052 1/1 Object#find_primes
0.001 0.000 0.000 0.001 1/1 Object#make_random_array
0.000 0.000 0.000 0.000 1/1 Object#find_largest
--------------------------------------------------------------------------------
0.052 0.000 0.000 0.052 1/1 Object#run_primes
98.35% 0.00% 0.052 0.000 0.000 0.052 1 Object#find_primes
0.052 0.000 0.000 0.051 1/1 Array#select
--------------------------------------------------------------------------------
0.052 0.000 0.000 0.051 1/1 Object#find_primes
98.34% 0.61% 0.052 0.000 0.000 0.051 1 Array#select
0.051 0.000 0.000 0.051 1000/1000 Object#is_prime
--------------------------------------------------------------------------------
0.051 0.000 0.000 0.051 1000/1000 Array#select
97.74% 0.93% 0.051 0.000 0.000 0.051 1000 Object#is_prime
0.051 0.051 0.000 0.000 1000/1001 Integer#upto
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1001 Object#find_largest
0.051 0.051 0.000 0.000 1000/1001 Object#is_prime
96.91% 96.91% 0.051 0.051 0.000 0.000 1001 Integer#upto
--------------------------------------------------------------------------------
0.001 0.000 0.000 0.001 1/1 Object#run_primes
1.51% 0.00% 0.001 0.000 0.000 0.001 1 Object#make_random_array
0.001 0.000 0.000 0.000 1/1 Array#each_index
0.000 0.000 0.000 0.000 1/1 Class#new
--------------------------------------------------------------------------------
0.001 0.000 0.000 0.000 1/1 Object#make_random_array
1.50% 0.56% 0.001 0.000 0.000 0.000 1 Array#each_index
0.000 0.000 0.000 0.000 1000/1000 Kernel#rand
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1000/1000 Array#each_index
0.94% 0.72% 0.000 0.000 0.000 0.000 1000 Kernel#rand
0.000 0.000 0.000 0.000 1000/1000 Kernel#respond_to_missing?
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1000/1000 Kernel#rand
0.22% 0.22% 0.000 0.000 0.000 0.000 1000 Kernel#respond_to_missing?
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#run_primes
0.12% 0.02% 0.000 0.000 0.000 0.000 1 Object#find_largest
0.000 0.000 0.000 0.000 1/1001 Integer#upto
0.000 0.000 0.000 0.000 1/1 Array#first
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#make_random_array
0.01% 0.00% 0.000 0.000 0.000 0.000 1 Class#new
0.000 0.000 0.000 0.000 1/1 Array#initialize
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Class#new
0.01% 0.01% 0.000 0.000 0.000 0.000 1 Array#initialize
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Object#find_largest
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Array#first
== 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.
wait - The time spent waiting for other threads in this method.
child - 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:
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 97.74% of the time was spent in Object#is_prime and its
children. Of that time, almost everything was contributed by Integer#upto.
Overall, Integer#upto was called 1001 times and 1000 of those calls were made
by Object#is_prime.
== 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 its children on behalf of the parent method.
self - The time spent in this method on behalf of the parent method.
child - The time spent in this method's children on behalf of the parent.
wait - The time spent waiting for other threads in this method's children on behalf of the parent.
calls - The number of times the parent method called the current method vs. the total number of calls of the current method.
Looking at the main entry for Integer#upto, we see that it was called 1000 times
from Object#is_prime and 1 time from 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 descendants, on behalf of the current method
self - The time spent in the child on behalf of the current method.
wait - The time spent waiting for other threads in the child's and its descendants on behalf of the current method.
child - The time spent in the child's descendants on behalf of the current method.
calls - The number of times the child method was called by the current method vs. the total number of calls of the child method.
If we look at the main entry for Objext#run_primes, we see that it called three
other methods - Object#find_primes, Object#make_random_array and
Object#find_largest.
|
