cddl/contrib/dtracetoolkit/Examples/pl_calltime_example.txt

   1 The following are examples of pl_calltime.d.
   2
   3 This script traces the elapsed time of Perl subroutines (functions) and
   4 prints a report. Here it traces the example program, Code/Perl/func_abc.pl.
   5
   6    # pl_calltime.d
   7    Tracing... Hit Ctrl-C to end.
   8    ^C
   9
  10    Count,
  11       FILE                 TYPE       NAME                                COUNT
  12       func_abc.pl          sub        func_a                                  1
  13       func_abc.pl          sub        func_b                                  1
  14       func_abc.pl          sub        func_c                                  1
  15       -                    total      -                                       3
  16
  17    Exclusive subroutine elapsed times (us),
  18       FILE                 TYPE       NAME                                TOTAL
  19       func_abc.pl          sub        func_a                            1006119
  20       func_abc.pl          sub        func_c                            1009978
  21       func_abc.pl          sub        func_b                            1010273
  22       -                    total      -                                 3026371
  23
  24    Inclusive subroutine elapsed times (us),
  25       FILE                 TYPE       NAME                                TOTAL
  26       func_abc.pl          sub        func_c                            1009978
  27       func_abc.pl          sub        func_b                            2020252
  28       func_abc.pl          sub        func_a                            3026371
  29
  30 In total, 3 subroutines were called, one of each.
  31
  32 The exclusive subroutine elapsed times show that each subroutine spent around
  33 1.0 seconds of time (~1000000 us) processing code - while not in other
  34 subroutines.
  35
  36 The inclusive subroutine elapsed times show that func_a() took around 3.0
  37 seconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0.
  38 The inclusive time includes the time spent in other subroutines called, and
  39 since func_a() called func_b() which called func_c(), these times make
  40 perfect sense.
  41
  42 These elapsed times are the absolute time from when the subroutine began to
  43 when it completed - which includes off-CPU time due to other system events
  44 such as I/O, scheduling, interrupts, etc.
  45
  46 Elapsed times are useful for identifying where latencies are.
  47 See Notes/ALLelapsed_notes.txt for more details. Also see
  48 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  49 detailed explanation of exclusive vs inclusive subroutine time.
  50
  51 If you study the func_abc.pl program alongside the above output, the numbers
  52 should make sense.
  53
  54
  55
  56 The following traces a Perl network interface statistics tool, "nicstat"
  57 version 0.99,
  58
  59 # pl_calltime.d
  60 Tracing... Hit Ctrl-C to end.
  61 ^C
  62
  63 Count,
  64    FILE                 TYPE       NAME                                COUNT
  65    Config.pm            sub        DESTROY                                 1
  66    Config.pm            sub        TIEHASH                                 1
  67    Config.pm            sub        import                                  1
  68    DynaLoader.pm        sub        bootstrap                               1
  69    DynaLoader.pm        sub        dl_load_flags                           1
  70    Std.pm               sub        getopts                                 1
  71    nicstat              sub        fetch_net_data                          1
  72    nicstat              sub        find_nets                               1
  73    register.pm          sub        import                                  1
  74    warnings.pm          sub        BEGIN                                   1
  75    Config.pm            sub        BEGIN                                   2
  76    DynaLoader.pm        sub        BEGIN                                   2
  77    Exporter.pm          sub        import                                  2
  78    register.pm          sub        mkMask                                  2
  79    vars.pm              sub        import                                  2
  80    Kstat.pm             sub        BEGIN                                   3
  81    nicstat              sub        BEGIN                                   3
  82    vars.pm              sub        BEGIN                                   3
  83    Config.pm            sub        FETCH                                   4
  84    strict.pm            sub        unimport                                4
  85    strict.pm            sub        import                                  5
  86    AutoLoader.pm        sub        BEGIN                                   6
  87    strict.pm            sub        bits                                    6
  88    nicstat              sub        print_neat                             18
  89    -                    total      -                                      72
  90
  91 Exclusive subroutine elapsed times (us),
  92    FILE                 TYPE       NAME                                TOTAL
  93    DynaLoader.pm        sub        dl_load_flags                           2
  94    Config.pm            sub        TIEHASH                                 3
  95    Config.pm            sub        DESTROY                                 9
  96    register.pm          sub        mkMask                                 11
  97    Config.pm            sub        import                                 12
  98    Config.pm            sub        FETCH                                  17
  99    strict.pm            sub        import                                 38
 100    Config.pm            sub        BEGIN                                  38
 101    strict.pm            sub        bits                                   49
 102    vars.pm              sub        import                                 59
 103    strict.pm            sub        unimport                               65
 104    AutoLoader.pm        sub        BEGIN                                  70
 105    Std.pm               sub        getopts                                78
 106    register.pm          sub        import                                 86
 107    Exporter.pm          sub        import                                112
 108    warnings.pm          sub        BEGIN                                 680
 109    DynaLoader.pm        sub        BEGIN                                1131
 110    DynaLoader.pm        sub        bootstrap                            1221
 111    nicstat              sub        print_neat                           2450
 112    vars.pm              sub        BEGIN                                2608
 113    Kstat.pm             sub        BEGIN                                3171
 114    nicstat              sub        BEGIN                                3963
 115    nicstat              sub        fetch_net_data                      45424
 116    nicstat              sub        find_nets                           55737
 117    -                    total      -                                  117047
 118
 119 Inclusive subroutine elapsed times (us),
 120    FILE                 TYPE       NAME                                TOTAL
 121    DynaLoader.pm        sub        dl_load_flags                           2
 122    Config.pm            sub        TIEHASH                                 3
 123    Config.pm            sub        DESTROY                                 9
 124    register.pm          sub        mkMask                                 11
 125    Config.pm            sub        import                                 12
 126    Config.pm            sub        FETCH                                  17
 127    strict.pm            sub        import                                 46
 128    strict.pm            sub        bits                                   49
 129    vars.pm              sub        import                                 59
 130    Config.pm            sub        BEGIN                                  64
 131    strict.pm            sub        unimport                               87
 132    register.pm          sub        import                                 97
 133    Std.pm               sub        getopts                               112
 134    Exporter.pm          sub        import                                112
 135    AutoLoader.pm        sub        BEGIN                                 140
 136    warnings.pm          sub        BEGIN                                 680
 137    DynaLoader.pm        sub        bootstrap                            1224
 138    nicstat              sub        print_neat                           2450
 139    vars.pm              sub        BEGIN                                3412
 140    DynaLoader.pm        sub        BEGIN                                4656
 141    Kstat.pm             sub        BEGIN                                8020
 142    nicstat              sub        BEGIN                               13313
 143    nicstat              sub        fetch_net_data                      45424
 144    nicstat              sub        find_nets                           55737
 145
 146 The output showed that the most time was spent in the subroutine find_nets(),
 147 with a total exclusive elapsed time of 55.7 ms. This also matches the
 148 total inclusive time, suggesting that find_nets() didn't call other
 149 subroutines.
 150