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.