diff options
Diffstat (limited to 'cddl/contrib/dtracetoolkit/Examples/pl_cputime_example.txt')
| -rw-r--r-- | cddl/contrib/dtracetoolkit/Examples/pl_cputime_example.txt | 151 |
1 files changed, 151 insertions, 0 deletions
diff --git a/cddl/contrib/dtracetoolkit/Examples/pl_cputime_example.txt b/cddl/contrib/dtracetoolkit/Examples/pl_cputime_example.txt new file mode 100644 index 0000000..5dc56ee --- /dev/null +++ b/cddl/contrib/dtracetoolkit/Examples/pl_cputime_example.txt @@ -0,0 +1,151 @@ +The following are examples of pl_cputime.d. + +This script traces the on-CPU time of Perl subroutines (functions) and +prints a report. Here it traces the example program, Code/Perl/func_slow.pl. + + # pl_cputime.d + Tracing... Hit Ctrl-C to end. + ^C + + Count, + FILE TYPE NAME COUNT + func_slow.pl sub func_a 1 + func_slow.pl sub func_b 1 + func_slow.pl sub func_c 1 + - total - 3 + + Exclusive subroutine on-CPU times (us), + FILE TYPE NAME TOTAL + func_slow.pl sub func_a 264193 + func_slow.pl sub func_b 538498 + func_slow.pl sub func_c 798961 + - total - 1601653 + + Inclusive subroutine on-CPU times (us), + FILE TYPE NAME TOTAL + func_slow.pl sub func_c 798961 + func_slow.pl sub func_b 1337459 + func_slow.pl sub func_a 1601653 + +In total, 3 subroutines were called, one each of func_a(), func_b() and +func_c(). + +The exclusive subroutine on-CPU times show that func_a() spent around 264.2 ms +on-CPU, func_b() spent 538.5 ms, and func_c() spent 799.0 ms. This exclusive +times excludes time spent in other subroutines. + +The inclusive subroutine on-CPU times show that func_c() spent around 799.0 ms +on-CPU, func_b() spent around 1.3 seconds, and func_a() spent around 1.6 +seconds. 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 perfect 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. + +If you study the func_slow.pl program alongside the above output, the numbers +should make sense. + + + +The following traces a Perl network interface statistics tool, "nicstat" +version 0.99, + +# pl_cputime.pl +Tracing... Hit Ctrl-C to end. +^C + +Count, + FILE TYPE NAME COUNT + Config.pm sub DESTROY 1 + Config.pm sub TIEHASH 1 + Config.pm sub import 1 + DynaLoader.pm sub bootstrap 1 + DynaLoader.pm sub dl_load_flags 1 + Std.pm sub getopts 1 + nicstat sub fetch_net_data 1 + nicstat sub find_nets 1 + register.pm sub import 1 + warnings.pm sub BEGIN 1 + Config.pm sub BEGIN 2 + DynaLoader.pm sub BEGIN 2 + Exporter.pm sub import 2 + register.pm sub mkMask 2 + vars.pm sub import 2 + Kstat.pm sub BEGIN 3 + nicstat sub BEGIN 3 + vars.pm sub BEGIN 3 + Config.pm sub FETCH 4 + strict.pm sub unimport 4 + strict.pm sub import 5 + AutoLoader.pm sub BEGIN 6 + strict.pm sub bits 6 + nicstat sub print_neat 18 + - total - 72 + +Exclusive subroutine on-CPU times (us), + FILE TYPE NAME TOTAL + DynaLoader.pm sub dl_load_flags 2 + Config.pm sub TIEHASH 2 + Config.pm sub DESTROY 6 + Config.pm sub BEGIN 7 + register.pm sub mkMask 8 + Config.pm sub import 11 + Config.pm sub FETCH 12 + strict.pm sub unimport 17 + strict.pm sub import 21 + AutoLoader.pm sub BEGIN 22 + Std.pm sub getopts 33 + strict.pm sub bits 40 + register.pm sub import 51 + vars.pm sub import 65 + Exporter.pm sub import 88 + nicstat sub print_neat 426 + warnings.pm sub BEGIN 598 + DynaLoader.pm sub bootstrap 677 + DynaLoader.pm sub BEGIN 1015 + Kstat.pm sub BEGIN 2627 + vars.pm sub BEGIN 2642 + nicstat sub BEGIN 3033 + nicstat sub fetch_net_data 42018 + nicstat sub find_nets 52094 + - total - 105526 + +Inclusive subroutine on-CPU times (us), + FILE TYPE NAME TOTAL + DynaLoader.pm sub dl_load_flags 2 + Config.pm sub TIEHASH 2 + Config.pm sub DESTROY 6 + register.pm sub mkMask 8 + Config.pm sub import 11 + Config.pm sub FETCH 12 + Config.pm sub BEGIN 19 + strict.pm sub import 28 + strict.pm sub unimport 35 + strict.pm sub bits 40 + AutoLoader.pm sub BEGIN 51 + register.pm sub import 59 + Std.pm sub getopts 63 + vars.pm sub import 65 + Exporter.pm sub import 88 + nicstat sub print_neat 426 + warnings.pm sub BEGIN 598 + DynaLoader.pm sub bootstrap 680 + vars.pm sub BEGIN 3313 + DynaLoader.pm sub BEGIN 4401 + Kstat.pm sub BEGIN 7124 + nicstat sub BEGIN 10916 + nicstat sub fetch_net_data 42018 + nicstat sub find_nets 52094 + +The output showed that the most CPU time was spent in the subroutine +find_nets(), with a total exclusive on-CPU time of 52.1 ms. This also matches +the total inclusive time, suggesting that find_nets() didn't call other +subroutines. + |
