cddl/contrib/dtracetoolkit/Examples/pl_cputime_example.txt

   1 The following are examples of pl_cputime.d.
   2
   3 This script traces the on-CPU time of Perl subroutines (functions) and
   4 prints a report. Here it traces the example program, Code/Perl/func_slow.pl.
   5
   6    # pl_cputime.d
   7    Tracing... Hit Ctrl-C to end.
   8    ^C
   9
  10    Count,
  11       FILE                 TYPE       NAME                                COUNT
  12       func_slow.pl         sub        func_a                                  1
  13       func_slow.pl         sub        func_b                                  1
  14       func_slow.pl         sub        func_c                                  1
  15       -                    total      -                                       3
  16
  17    Exclusive subroutine on-CPU times (us),
  18       FILE                 TYPE       NAME                                TOTAL
  19       func_slow.pl         sub        func_a                             264193
  20       func_slow.pl         sub        func_b                             538498
  21       func_slow.pl         sub        func_c                             798961
  22       -                    total      -                                 1601653
  23
  24    Inclusive subroutine on-CPU times (us),
  25       FILE                 TYPE       NAME                                TOTAL
  26       func_slow.pl         sub        func_c                             798961
  27       func_slow.pl         sub        func_b                            1337459
  28       func_slow.pl         sub        func_a                            1601653
  29
  30 In total, 3 subroutines were called, one each of func_a(), func_b() and
  31 func_c().
  32
  33 The exclusive subroutine on-CPU times show that func_a() spent around 264.2 ms
  34 on-CPU, func_b() spent 538.5 ms, and func_c() spent 799.0 ms. This exclusive
  35 times excludes time spent in other subroutines.
  36
  37 The inclusive subroutine on-CPU times show that func_c() spent around 799.0 ms
  38 on-CPU, func_b() spent around 1.3 seconds, and func_a() spent around 1.6
  39 seconds. This inclusive time includes the time spent in other subroutines
  40 called, and since func_a() called func_b() which called func_c(), these
  41 times make perfect sense.
  42
  43 These on-CPU times are the time the thread spent running on a CPU, from when
  44 the subroutine began to when it completed. This does not include time
  45 spent off-CPU time such as sleeping for I/O or waiting for scheduling.
  46
  47 On-CPU times are useful for showing who is causing the CPUs to be busy.
  48 See Notes/ALLoncpu_notes.txt for more details. Also see
  49 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  50 detailed explanation of exclusive vs inclusive subroutine time.
  51
  52 If you study the func_slow.pl program alongside the above output, the numbers
  53 should make sense.
  54
  55
  56
  57 The following traces a Perl network interface statistics tool, "nicstat"
  58 version 0.99,
  59
  60 # pl_cputime.pl
  61 Tracing... Hit Ctrl-C to end.
  62 ^C
  63
  64 Count,
  65    FILE                 TYPE       NAME                                COUNT
  66    Config.pm            sub        DESTROY                                 1
  67    Config.pm            sub        TIEHASH                                 1
  68    Config.pm            sub        import                                  1
  69    DynaLoader.pm        sub        bootstrap                               1
  70    DynaLoader.pm        sub        dl_load_flags                           1
  71    Std.pm               sub        getopts                                 1
  72    nicstat              sub        fetch_net_data                          1
  73    nicstat              sub        find_nets                               1
  74    register.pm          sub        import                                  1
  75    warnings.pm          sub        BEGIN                                   1
  76    Config.pm            sub        BEGIN                                   2
  77    DynaLoader.pm        sub        BEGIN                                   2
  78    Exporter.pm          sub        import                                  2
  79    register.pm          sub        mkMask                                  2
  80    vars.pm              sub        import                                  2
  81    Kstat.pm             sub        BEGIN                                   3
  82    nicstat              sub        BEGIN                                   3
  83    vars.pm              sub        BEGIN                                   3
  84    Config.pm            sub        FETCH                                   4
  85    strict.pm            sub        unimport                                4
  86    strict.pm            sub        import                                  5
  87    AutoLoader.pm        sub        BEGIN                                   6
  88    strict.pm            sub        bits                                    6
  89    nicstat              sub        print_neat                             18
  90    -                    total      -                                      72
  91
  92 Exclusive subroutine on-CPU times (us),
  93    FILE                 TYPE       NAME                                TOTAL
  94    DynaLoader.pm        sub        dl_load_flags                           2
  95    Config.pm            sub        TIEHASH                                 2
  96    Config.pm            sub        DESTROY                                 6
  97    Config.pm            sub        BEGIN                                   7
  98    register.pm          sub        mkMask                                  8
  99    Config.pm            sub        import                                 11
 100    Config.pm            sub        FETCH                                  12
 101    strict.pm            sub        unimport                               17
 102    strict.pm            sub        import                                 21
 103    AutoLoader.pm        sub        BEGIN                                  22
 104    Std.pm               sub        getopts                                33
 105    strict.pm            sub        bits                                   40
 106    register.pm          sub        import                                 51
 107    vars.pm              sub        import                                 65
 108    Exporter.pm          sub        import                                 88
 109    nicstat              sub        print_neat                            426
 110    warnings.pm          sub        BEGIN                                 598
 111    DynaLoader.pm        sub        bootstrap                             677
 112    DynaLoader.pm        sub        BEGIN                                1015
 113    Kstat.pm             sub        BEGIN                                2627
 114    vars.pm              sub        BEGIN                                2642
 115    nicstat              sub        BEGIN                                3033
 116    nicstat              sub        fetch_net_data                      42018
 117    nicstat              sub        find_nets                           52094
 118    -                    total      -                                  105526
 119
 120 Inclusive subroutine on-CPU times (us),
 121    FILE                 TYPE       NAME                                TOTAL
 122    DynaLoader.pm        sub        dl_load_flags                           2
 123    Config.pm            sub        TIEHASH                                 2
 124    Config.pm            sub        DESTROY                                 6
 125    register.pm          sub        mkMask                                  8
 126    Config.pm            sub        import                                 11
 127    Config.pm            sub        FETCH                                  12
 128    Config.pm            sub        BEGIN                                  19
 129    strict.pm            sub        import                                 28
 130    strict.pm            sub        unimport                               35
 131    strict.pm            sub        bits                                   40
 132    AutoLoader.pm        sub        BEGIN                                  51
 133    register.pm          sub        import                                 59
 134    Std.pm               sub        getopts                                63
 135    vars.pm              sub        import                                 65
 136    Exporter.pm          sub        import                                 88
 137    nicstat              sub        print_neat                            426
 138    warnings.pm          sub        BEGIN                                 598
 139    DynaLoader.pm        sub        bootstrap                             680
 140    vars.pm              sub        BEGIN                                3313
 141    DynaLoader.pm        sub        BEGIN                                4401
 142    Kstat.pm             sub        BEGIN                                7124
 143    nicstat              sub        BEGIN                               10916
 144    nicstat              sub        fetch_net_data                      42018
 145    nicstat              sub        find_nets                           52094
 146
 147 The output showed that the most CPU time was spent in the subroutine
 148 find_nets(), with a total exclusive on-CPU time of 52.1 ms. This also matches
 149 the total inclusive time, suggesting that find_nets() didn't call other
 150 subroutines.
 151