diff options
Diffstat (limited to 'Examples/pl_cpudist_example.txt')
| -rw-r--r-- | Examples/pl_cpudist_example.txt | 470 |
1 files changed, 470 insertions, 0 deletions
diff --git a/Examples/pl_cpudist_example.txt b/Examples/pl_cpudist_example.txt new file mode 100644 index 000000000000..a2ccff83f4ed --- /dev/null +++ b/Examples/pl_cpudist_example.txt @@ -0,0 +1,470 @@ +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. + |