200 lines
10 KiB
Plaintext
200 lines
10 KiB
Plaintext
|
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.
|
||
|
|
|