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.