1 The following are examples of rb_cpudist.d.
3 This script traces the on-CPU time of Ruby functions and prints a report in
4 the form of a histogram. Here it traces the example program,
8 Tracing... Hit Ctrl-C to end.
12 ., obj-new, NoMemoryError
13 value ------------- Distribution ------------- count
15 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
18 ., obj-new, SystemStackError
19 value ------------- Distribution ------------- count
21 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
24 ., obj-new, ThreadGroup
25 value ------------- Distribution ------------- count
27 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
31 value ------------- Distribution ------------- count
33 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
37 value ------------- Distribution ------------- count
39 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
45 Exclusive function on-CPU times (us),
46 func_slow.rb, func, Module::method_added
47 value ------------- Distribution ------------- count
49 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
52 func_slow.rb, func, Object::print
53 value ------------- Distribution ------------- count
55 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
59 func_slow.rb, func, IO::write
60 value ------------- Distribution ------------- count
62 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
66 func_slow.rb, func, Object::func_a
67 value ------------- Distribution ------------- count
69 262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
72 func_slow.rb, func, Object::func_b
73 value ------------- Distribution ------------- count
75 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
78 func_slow.rb, func, Fixnum::<
79 value ------------- Distribution ------------- count
81 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556
91 func_slow.rb, func, Object::func_c
92 value ------------- Distribution ------------- count
94 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
97 func_slow.rb, func, Fixnum::+
98 value ------------- Distribution ------------- count
100 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062
112 Inclusive function on-CPU times (us),
113 func_slow.rb, func, Module::method_added
114 value ------------- Distribution ------------- count
116 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
119 func_slow.rb, func, IO::write
120 value ------------- Distribution ------------- count
122 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
126 func_slow.rb, func, Object::print
127 value ------------- Distribution ------------- count
129 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
133 func_slow.rb, func, Fixnum::<
134 value ------------- Distribution ------------- count
136 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556
146 func_slow.rb, func, Fixnum::+
147 value ------------- Distribution ------------- count
149 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062
160 func_slow.rb, func, Object::func_b
161 value ------------- Distribution ------------- count
163 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
166 func_slow.rb, func, Object::func_c
167 value ------------- Distribution ------------- count
169 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
172 func_slow.rb, func, Object::func_a
173 value ------------- Distribution ------------- count
175 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
178 You can see that the results are in three sections.
180 The first section shows us the on-CPU time for actions that were not of the
183 The second section, Exclusive function on-CPU times, shows us the time spent
184 on-CPU by various functions, not including time spent in subroutines. You can
185 see here that Object::print had two instances of being on-CPU between 4
186 microseconds and 7 microseconds, and once instance of being on-CPU between 8
187 microseconds and 15 microseconds.
189 The third section, Inclusive function on-CPU times, shows us the time spent
190 on-CPU by various functions, including that time spent in subroutines called
191 by those functions. You can see that here Object::print had two instances
192 of being on-CPU between 32 microseconds and 63 microseconds, and one instance
193 of being on-CPU between 64 microseconds and 127 microseconds.
195 It is important to pay close attention to the third column, "count" as this
196 will indicate if there were any instances in a particular timeframe, even if
197 the number is too small to show up on the histogram clearly. See Inclusive
198 function on-CPU time for Fixnum::+ for an example.