xref: /src/external/cddl/dtracetoolkit/dist/Docs/Examples/pl_cputime_example.txt

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.