cddl/contrib/dtracetoolkit/Examples/rb_cpudist_example.txt


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

The following are examples of rb_cpudist.d.

This script traces the on-CPU time of Ruby functions and prints a report in
the form of a histogram.  Here it traces the example program, 
Code/Ruby/func_slow.rb

# rb_cpudist.d
Tracing... Hit Ctrl-C to end.
^C

On-CPU times (us),
   ., obj-new, NoMemoryError 
           value  ------------- Distribution ------------- count    
               1 |                                         0        
               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
               4 |                                         0        

   ., obj-new, SystemStackError 
           value  ------------- Distribution ------------- count    
               1 |                                         0        
               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
               4 |                                         0        

   ., obj-new, ThreadGroup 
           value  ------------- Distribution ------------- count    
               4 |                                         0        
               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
              16 |                                         0        

   ., obj-new, fatal 
           value  ------------- Distribution ------------- count    
               4 |                                         0        
               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
              16 |                                         0        

   ., obj-new, Object 
           value  ------------- Distribution ------------- count    
               1 |                                         0        
               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2        
               4 |                                         0        
               8 |@@@@@@@@@@@@@                            1        
              16 |                                         0        


Exclusive function on-CPU times (us),
   func_slow.rb, func, Module::method_added 
           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
               2 |                                         0        

   func_slow.rb, func, Object::print 
           value  ------------- Distribution ------------- count    
               2 |                                         0        
               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2        
               8 |@@@@@@@@@@@@@                            1        
              16 |                                         0        

   func_slow.rb, func, IO::write 
           value  ------------- Distribution ------------- count    
              16 |                                         0        
              32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2        
              64 |@@@@@@@@@@@@@                            1        
             128 |                                         0        

   func_slow.rb, func, Object::func_a 
           value  ------------- Distribution ------------- count    
          131072 |                                         0        
          262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
          524288 |                                         0        

   func_slow.rb, func, Object::func_b 
           value  ------------- Distribution ------------- count    
          262144 |                                         0        
          524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
         1048576 |                                         0        

   func_slow.rb, func, Fixnum::< 
           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556   
               2 |                                         72       
               4 |                                         35       
               8 |                                         128      
              16 |                                         158      
              32 |                                         49       
              64 |                                         3        
             128 |                                         2        
             256 |                                         0        

   func_slow.rb, func, Object::func_c 
           value  ------------- Distribution ------------- count    
          524288 |                                         0        
         1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
         2097152 |                                         0        

   func_slow.rb, func, Fixnum::+ 
           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062  
               2 |                                         138      
               4 |                                         74       
               8 |                                         279      
              16 |                                         344      
              32 |                                         91       
              64 |                                         9        
             128 |                                         0        
             256 |                                         3        
             512 |                                         0        


Inclusive function on-CPU times (us),
   func_slow.rb, func, Module::method_added 
           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
               2 |                                         0        

   func_slow.rb, func, IO::write 
           value  ------------- Distribution ------------- count    
              16 |                                         0        
              32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2        
              64 |@@@@@@@@@@@@@                            1        
             128 |                                         0        

   func_slow.rb, func, Object::print 
           value  ------------- Distribution ------------- count    
              16 |                                         0        
              32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2        
              64 |@@@@@@@@@@@@@                            1        
             128 |                                         0        

   func_slow.rb, func, Fixnum::< 
           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556   
               2 |                                         72       
               4 |                                         35       
               8 |                                         128      
              16 |                                         158      
              32 |                                         49       
              64 |                                         3        
             128 |                                         2        
             256 |                                         0        

   func_slow.rb, func, Fixnum::+ 
           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062  
               2 |                                         138      
               4 |                                         74       
               8 |                                         279      
              16 |                                         344      
              32 |                                         91       
              64 |                                         9        
             128 |                                         0        
             256 |                                         3        
             512 |                                         0        

   func_slow.rb, func, Object::func_b 
           value  ------------- Distribution ------------- count    
         1048576 |                                         0        
         2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
         4194304 |                                         0        

   func_slow.rb, func, Object::func_c 
           value  ------------- Distribution ------------- count    
         1048576 |                                         0        
         2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
         4194304 |                                         0        

   func_slow.rb, func, Object::func_a 
           value  ------------- Distribution ------------- count    
         2097152 |                                         0        
         4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
         8388608 |                                         0        

You can see that the results are in three sections.  

The first section shows us the on-CPU time for actions that were not of the
type 'func'.  

The second section, Exclusive function on-CPU times, shows us the time spent
on-CPU by various functions, not including time spent in subroutines.  You can
see here that Object::print had two instances of being on-CPU between 4
microseconds and 7 microseconds, and once instance of being on-CPU between 8
microseconds and 15 microseconds. 

The third section, Inclusive function on-CPU times, shows us the time spent
on-CPU by various functions, including that time spent in subroutines called
by those functions.  You can see that here Object::print had two instances 
of being on-CPU between 32 microseconds and 63 microseconds, and one instance 
of being on-CPU between 64 microseconds and 127 microseconds.

It is important to pay close attention to the third column, "count" as this
will indicate if there were any instances in a particular timeframe, even if
the number is too small to show up on the histogram clearly.  See Inclusive
function on-CPU time for Fixnum::+ for an example.