The following are examples of pl_cpudist.d.
This script traces the on-CPU time of Perl subroutines (functions) and
prints a report containing distribution plots per subroutine. Here it
traces the example program, Code/Perl/func_slow.pl.
# pl_cpudist.d
Tracing... Hit Ctrl-C to end.
^C
Exclusive subroutine on-CPU times (us),
func_slow.pl, sub, func_a
value ------------- Distribution ------------- count
131072 | 0
262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
524288 | 0
func_slow.pl, sub, func_b
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
func_slow.pl, sub, func_c
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
Inclusive subroutine on-CPU times (us),
func_slow.pl, sub, func_c
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
func_slow.pl, sub, func_a
value ------------- Distribution ------------- count
524288 | 0
1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
2097152 | 0
func_slow.pl, sub, func_b
value ------------- Distribution ------------- count
524288 | 0
1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
2097152 | 0
The exclusive subroutine on-CPU times show that func_a() spent between
262 ms and 524 ms on-CPU, while func_b() and func_c() both spent between
524 ms and 1048 ms on-CPU.
The inclusive subroutine on-CPU times show that func_c() spent between 0.5 and
1.0 seconds, and both func_b() and func_a() spent between 1.0 and 2.1 seconds
of CPU time. This inclusive time includes the time spent in other subroutines
called, and since func_a() called func_b() which called func_c(), these times
make sense.
These on-CPU times are the time the thread spent running on a CPU, from when
the subroutine began to when it completed. This does not include time
spent off-CPU time such as sleeping for I/O or waiting for scheduling.
On-CPU times are useful for showing who is causing the CPUs to be busy.
See Notes/ALLoncpu_notes.txt for more details. Also see
Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
detailed explanation of exclusive vs inclusive subroutine time.
The following traces a Perl network interface statistics tool, "nicstat"
version 0.99,
# pl_cpudist.pl
Tracing... Hit Ctrl-C to end.
^C
Exclusive subroutine on-CPU times (us),
Config.pm, sub, TIEHASH
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4 | 0
DynaLoader.pm, sub, dl_load_flags
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4 | 0
Config.pm, sub, BEGIN
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
4 | 0
Config.pm, sub, DESTROY
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
register.pm, sub, mkMask
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@ 1
4 |@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
Config.pm, sub, import
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
16 | 0
Config.pm, sub, FETCH
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
4 |@@@@@@@@@@ 1
8 | 0
strict.pm, sub, unimport
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
8 |@@@@@@@@@@ 1
16 | 0
Std.pm, sub, getopts
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
64 | 0
register.pm, sub, import
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
64 | 0
strict.pm, sub, import
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@ 2
4 |@@@@@@@@ 1
8 |@@@@@@@@ 1
16 |@@@@@@@@ 1
32 | 0
strict.pm, sub, bits
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
8 |@@@@@@@ 1
16 |@@@@@@@ 1
32 | 0
AutoLoader.pm, sub, BEGIN
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@ 1
2 |@@@@@@@@@@@@@ 2
4 |@@@@@@@@@@@@@ 2
8 | 0
16 | 0
32 |@@@@@@@ 1
64 | 0
vars.pm, sub, import
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
64 | 0
Exporter.pm, sub, import
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@ 1
32 | 0
64 |@@@@@@@@@@@@@@@@@@@@ 1
128 | 0
nicstat, sub, print_neat
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 16
32 |@@ 1
64 |@@ 1
128 | 0
DynaLoader.pm, sub, bootstrap
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1024 | 0
warnings.pm, sub, BEGIN
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1024 | 0
DynaLoader.pm, sub, BEGIN
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@ 1
512 |@@@@@@@@@@@@@@@@@@@@ 1
1024 | 0
vars.pm, sub, BEGIN
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@ 1
2 |@@@@@@@@@@@@@ 1
4 | 0
8 | 0
16 | 0
32 | 0
64 | 0
128 | 0
256 | 0
512 | 0
1024 | 0
2048 |@@@@@@@@@@@@@ 1
4096 | 0
Kstat.pm, sub, BEGIN
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
4 | 0
8 | 0
16 | 0
32 | 0
64 | 0
128 | 0
256 | 0
512 | 0
1024 | 0
2048 |@@@@@@@@@@@@@ 1
4096 | 0
nicstat, sub, BEGIN
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
512 | 0
1024 | 0
2048 |@@@@@@@@@@@@@ 1
4096 | 0
nicstat, sub, fetch_net_data
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
65536 | 0
nicstat, sub, find_nets
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
65536 | 0
Inclusive subroutine on-CPU times (us),
Config.pm, sub, TIEHASH
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4 | 0
DynaLoader.pm, sub, dl_load_flags
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4 | 0
Config.pm, sub, DESTROY
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
register.pm, sub, mkMask
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@ 1
4 |@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
Config.pm, sub, import
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
16 | 0
Config.pm, sub, FETCH
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
4 |@@@@@@@@@@ 1
8 | 0
Config.pm, sub, BEGIN
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@ 1
32 | 0
strict.pm, sub, unimport
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
16 | 0
strict.pm, sub, import
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@ 2
4 | 0
8 |@@@@@@@@@@@@@@@@ 2
16 |@@@@@@@@ 1
32 | 0
strict.pm, sub, bits
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
8 |@@@@@@@ 1
16 |@@@@@@@ 1
32 | 0
Std.pm, sub, getopts
value ------------- Distribution ------------- count
32 | 0
64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
128 | 0
register.pm, sub, import
value ------------- Distribution ------------- count
32 | 0
64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
128 | 0
vars.pm, sub, import
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
64 | 0
AutoLoader.pm, sub, BEGIN
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@ 1
2 | 0
4 |@@@@@@@ 1
8 |@@@@@@@@@@@@@ 2
16 |@@@@@@@ 1
32 |@@@@@@@ 1
64 | 0
Exporter.pm, sub, import
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@ 1
32 | 0
64 |@@@@@@@@@@@@@@@@@@@@ 1
128 | 0
nicstat, sub, print_neat
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 16
32 |@@ 1
64 |@@ 1
128 | 0
DynaLoader.pm, sub, bootstrap
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1024 | 0
warnings.pm, sub, BEGIN
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1024 | 0
vars.pm, sub, BEGIN
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@ 1
2 | 0
4 | 0
8 | 0
16 |@@@@@@@@@@@@@ 1
32 | 0
64 | 0
128 | 0
256 | 0
512 | 0
1024 | 0
2048 |@@@@@@@@@@@@@ 1
4096 | 0
DynaLoader.pm, sub, BEGIN
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@@@@@@@@ 1
1024 | 0
2048 |@@@@@@@@@@@@@@@@@@@@ 1
4096 | 0
Kstat.pm, sub, BEGIN
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@ 1
8 | 0
16 | 0
32 |@@@@@@@@@@@@@ 1
64 | 0
128 | 0
256 | 0
512 | 0
1024 | 0
2048 | 0
4096 |@@@@@@@@@@@@@ 1
8192 | 0
nicstat, sub, BEGIN
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@ 1
512 | 0
1024 | 0
2048 |@@@@@@@@@@@@@ 1
4096 | 0
8192 |@@@@@@@@@@@@@ 1
16384 | 0
nicstat, sub, fetch_net_data
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
65536 | 0
nicstat, sub, find_nets
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
65536 | 0
As an example of interpreting the output: the inclusive on-CPU time for
the "print_neat" subroutine in "nicstat",
nicstat, sub, print_neat
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 16
32 |@@ 1
64 |@@ 1
128 | 0
shows that "print_neat" was called 18 times, 16 of which spent between 16
and 31 microseconds on-CPU, once between 32 and 63 microseconds, and once
between 64 and 127 microseconds.