The following are examples of pl_calldist.d.
This script traces the elapsed time of Perl subroutines (functions) and
prints a report containing distribution plots per subroutine. Here it
traces the example program, Code/Perl/func_abc.pl.
# pl_calldist.d
Tracing... Hit Ctrl-C to end.
^C
Exclusive subroutine elapsed times (us),
func_abc.pl, sub, func_a
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
func_abc.pl, sub, func_b
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
func_abc.pl, sub, func_c
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
Inclusive subroutine elapsed times (us),
func_abc.pl, sub, func_c
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
func_abc.pl, sub, func_b
value ------------- Distribution ------------- count
524288 | 0
1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
2097152 | 0
func_abc.pl, sub, func_a
value ------------- Distribution ------------- count
1048576 | 0
2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4194304 | 0
In total, 3 subroutines were called - func_a(), func_b(), and func_c().
The exclusive subroutine elapsed times show that each subroutine spent
between 524 and 1048 ms. This exclusive time excludes the time spent in
other subroutines.
The inclusive subroutine elapsed times show that func_c() took between 0.5 and
1.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took
between 2.1 and 4.2 seconds to execute. 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 elapsed times are the absolute time from when the subroutine began to
when it completed - which includes off-CPU time due to other system events
such as I/O, scheduling, interrupts, etc.
Elapsed times are useful for identifying where latencies are.
See Notes/ALLelapsed_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_calldist.d
Tracing... Hit Ctrl-C to end.
^C
Exclusive subroutine elapsed times (us),
DynaLoader.pm, sub, dl_load_flags
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4 | 0
Config.pm, sub, TIEHASH
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
Config.pm, sub, DESTROY
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
16 | 0
Config.pm, sub, import
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
16 | 0
register.pm, sub, mkMask
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
8 | 0
Config.pm, sub, FETCH
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@ 2
4 |@@@@@@@@@@@@@@@@@@@@ 2
8 | 0
Config.pm, sub, BEGIN
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@ 1
16 |@@@@@@@@@@@@@@@@@@@@ 1
32 | 0
strict.pm, sub, import
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@ 1
4 |@@@@@@@@@@@@@@@@ 2
8 |@@@@@@@@ 1
16 |@@@@@@@@ 1
32 | 0
strict.pm, sub, bits
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
8 |@@@@@@@ 1
16 |@@@@@@@ 1
32 | 0
strict.pm, sub, unimport
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
16 |@@@@@@@@@@ 1
32 | 0
AutoLoader.pm, sub, BEGIN
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@ 1
4 |@@@@@@@ 1
8 |@@@@@@@@@@@@@@@@@@@@ 3
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
Exporter.pm, sub, import
value ------------- Distribution ------------- count
16 | 0
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 | 0
1024 |@@@@@@@@@@@@@@@@@@@@ 1
2048 | 0
nicstat, sub, print_neat
value ------------- Distribution ------------- count
32 | 0
64 |@@@@@@@@@@@@@@@@@@@@@@ 10
128 |@@@@@@@@@@@@@@@@@@ 8
256 | 0
vars.pm, sub, BEGIN
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@ 1
4 | 0
8 |@@@@@@@@@@@@@ 1
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
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
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 |@@@@@@@@@@@@@ 1
512 |@@@@@@@@@@@@@ 1
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 elapsed times (us),
DynaLoader.pm, sub, dl_load_flags
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4 | 0
Config.pm, sub, TIEHASH
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
8 | 0
Config.pm, sub, DESTROY
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
16 | 0
Config.pm, sub, import
value ------------- Distribution ------------- count
4 | 0
8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
16 | 0
register.pm, sub, mkMask
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
8 | 0
Config.pm, sub, FETCH
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@@@@@@@@ 2
4 |@@@@@@@@@@@@@@@@@@@@ 2
8 | 0
strict.pm, sub, bits
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
8 |@@@@@@@ 1
16 |@@@@@@@ 1
32 | 0
strict.pm, sub, import
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@ 1
4 |@@@@@@@@@@@@@@@@ 2
8 | 0
16 |@@@@@@@@@@@@@@@@ 2
32 | 0
Config.pm, sub, BEGIN
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@ 1
32 |@@@@@@@@@@@@@@@@@@@@ 1
64 | 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
strict.pm, sub, unimport
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
32 | 0
vars.pm, sub, import
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
64 | 0
AutoLoader.pm, sub, BEGIN
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@ 1
4 |@@@@@@@ 1
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@ 3
32 |@@@@@@@ 1
64 | 0
Exporter.pm, sub, import
value ------------- Distribution ------------- count
16 | 0
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
nicstat, sub, print_neat
value ------------- Distribution ------------- count
32 | 0
64 |@@@@@@@@@@@@@@@@@@@@@@ 10
128 |@@@@@@@@@@@@@@@@@@ 8
256 | 0
vars.pm, sub, BEGIN
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@ 1
4 | 0
8 | 0
16 | 0
32 |@@@@@@@@@@@@@ 1
64 | 0
128 | 0
256 | 0
512 | 0
1024 | 0
2048 |@@@@@@@@@@@@@ 1
4096 | 0
DynaLoader.pm, sub, BEGIN
value ------------- Distribution ------------- count
512 | 0
1024 |@@@@@@@@@@@@@@@@@@@@ 1
2048 |@@@@@@@@@@@@@@@@@@@@ 1
4096 | 0
Kstat.pm, sub, BEGIN
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@ 1
32 |@@@@@@@@@@@@@ 1
64 | 0
128 | 0
256 | 0
512 | 0
1024 | 0
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@ 1
16384 | 0
nicstat, sub, BEGIN
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@ 1
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 elapsed time for
the "print_neat" subroutine in "nicstat",
nicstat, sub, print_neat
value ------------- Distribution ------------- count
32 | 0
64 |@@@@@@@@@@@@@@@@@@@@@@ 10
128 |@@@@@@@@@@@@@@@@@@ 8
256 | 0
shows that "print_neat" was called 18 times, 10 of which took between 64
and 127 microseconds, and 8 of which took between 128 and 255 microseconds.