471 lines
24 KiB
Plaintext
471 lines
24 KiB
Plaintext
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.
|
|
|