cddl/contrib/dtracetoolkit/Examples/pl_flowtime_example.txt

   1 The following are examples of pl_flowtime.d.
   2
   3 This is a simple script to trace the flow of Perl subroutines (functions).
   4 Here it traces the example program, Code/Perl/func_abc.pl.
   5
   6    # pl_flowtime.d
   7      C TIME(us)         FILE             DELTA(us)  -- SUB
   8      0 4201460363351    func_abc.pl              2 -> func_a
   9      0 4201461370041    func_abc.pl        1006689   -> func_b
  10      0 4201462380038    func_abc.pl        1009997     -> func_c
  11      0 4201463390094    func_abc.pl        1010055     <- func_c
  12      0 4201463390117    func_abc.pl             23   <- func_b
  13      0 4201463390126    func_abc.pl              8 <- func_a
  14    ^C
  15
  16 As each subroutine is entered, the third column is indented by 2 spaces. This
  17 shows which subroutine is calling who - the output above begins by showing that
  18 func_a() began, and then called func_b().
  19
  20 The DELTA(us) column shows time from that line to the previous line, and
  21 so can be a bit tricky to read. For example, the second line of data output
  22 (skipping the header) reads as "the time from func_a() beginning to
  23 func_b() beginning was 1006689 us, or 1.01 seconds".
  24
  25 If the output looks shuffled, check the CPU "C" and "TIME" columns, and
  26 post sort based on TIME if necessary.
  27
  28 See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
  29
  30
  31
  32 The following traces a Perl network interface statistics tool, "nicstat"
  33 version 0.99,
  34
  35 # pl_flowtime.d
  36   C TIME(us)         FILE             DELTA(us)  -- SUB
  37   0 4201691465151    nicstat                  2 -> BEGIN
  38   0 4201691465593    strict.pm              441   -> bits
  39   0 4201691465625    strict.pm               32   <- bits
  40   0 4201691465655    strict.pm               29   -> import
  41   0 4201691465676    strict.pm               21   <- import
  42   0 4201691465684    nicstat                  7 <- BEGIN
  43   0 4201691465710    nicstat                 25 -> BEGIN
  44   0 4201691468038    Exporter.pm           2328   -> import
  45   0 4201691468121    Exporter.pm             82   <- import
  46   0 4201691468133    nicstat                 12 <- BEGIN
  47   0 4201691468160    nicstat                 26 -> BEGIN
  48   0 4201691468367    Kstat.pm               207   -> BEGIN
  49   0 4201691468378    strict.pm               10     -> import
  50   0 4201691468388    strict.pm               10     <- import
  51   0 4201691468396    Kstat.pm                 8   <- BEGIN
  52   0 4201691468419    Kstat.pm                23   -> BEGIN
  53   0 4201691468612    DynaLoader.pm          192     -> BEGIN
  54   0 4201691468685    vars.pm                 73       -> BEGIN
  55   0 4201691468694    vars.pm                  8       <- BEGIN
  56   0 4201691468727    vars.pm                 33       -> BEGIN
  57   0 4201691469199    warnings.pm            471         -> BEGIN
  58   0 4201691469863    warnings.pm            663         <- BEGIN
  59   0 4201691471965    register.pm           2102         -> import
  60   0 4201691471986    register.pm             21           -> mkMask
  61   0 4201691472000    register.pm             13           <- mkMask
  62   0 4201691472052    register.pm             52           -> mkMask
  63   0 4201691472063    register.pm             10           <- mkMask
  64   0 4201691472074    register.pm             10         <- import
  65   0 4201691472081    vars.pm                  7       <- BEGIN
  66   0 4201691472109    vars.pm                 28       -> BEGIN
  67   0 4201691472118    strict.pm                8         -> import
  68   0 4201691472126    strict.pm                8           -> bits
  69   0 4201691472139    strict.pm               12           <- bits
  70   0 4201691472148    strict.pm                9         <- import
  71   0 4201691472155    vars.pm                  7       <- BEGIN
  72   0 4201691472450    vars.pm                294       -> import
  73   0 4201691472501    vars.pm                 51       <- import
  74   0 4201691472509    DynaLoader.pm            7     <- BEGIN
  75   0 4201691472557    DynaLoader.pm           48     -> BEGIN
  76   0 4201691472650    Config.pm               92       -> BEGIN
  77   0 4201691472658    strict.pm                8         -> import
  78   0 4201691472667    strict.pm                8         <- import
  79   0 4201691472675    Config.pm                7       <- BEGIN
  80   0 4201691472809    Config.pm              133       -> BEGIN
  81   0 4201691472817    strict.pm                8         -> unimport
  82   0 4201691472825    strict.pm                8           -> bits
  83   0 4201691472852    strict.pm               26           <- bits
  84   0 4201691472868    strict.pm               16         <- unimport
  85   0 4201691472876    Config.pm                7       <- BEGIN
  86   0 4201691473222    Config.pm              345       -> TIEHASH
  87   0 4201691473231    Config.pm                9       <- TIEHASH
  88   0 4201691473275    Config.pm               43       -> import
  89   0 4201691473292    Config.pm               17       <- import
  90   0 4201691473301    DynaLoader.pm            8     <- BEGIN
  91   0 4201691474650    AutoLoader.pm         1349     -> BEGIN
  92   0 4201691474661    strict.pm               10       -> import
  93   0 4201691474670    strict.pm                9       <- import
  94   0 4201691474679    AutoLoader.pm            8     <- BEGIN
  95   0 4201691474701    AutoLoader.pm           21     -> BEGIN
  96   0 4201691474709    AutoLoader.pm            8     <- BEGIN
  97   0 4201691474797    AutoLoader.pm           88     -> BEGIN
  98   0 4201691474810    AutoLoader.pm           12     <- BEGIN
  99   0 4201691475186    AutoLoader.pm          376     -> BEGIN
 100   0 4201691475195    strict.pm                9       -> unimport
 101   0 4201691475203    strict.pm                7         -> bits
 102   0 4201691475214    strict.pm               10         <- bits
 103   0 4201691475223    strict.pm                8       <- unimport
 104   0 4201691475230    AutoLoader.pm            7     <- BEGIN
 105   0 4201691475435    AutoLoader.pm          204     -> BEGIN
 106   0 4201691475444    strict.pm                8       -> unimport
 107   0 4201691475451    strict.pm                7         -> bits
 108   0 4201691475462    strict.pm               10         <- bits
 109   0 4201691475470    strict.pm                8       <- unimport
 110   0 4201691475478    AutoLoader.pm            7     <- BEGIN
 111   0 4201691475697    AutoLoader.pm          219     -> BEGIN
 112   0 4201691475706    strict.pm                8       -> unimport
 113   0 4201691475714    strict.pm                7         -> bits
 114   0 4201691475724    strict.pm               10         <- bits
 115   0 4201691475732    strict.pm                8       <- unimport
 116   0 4201691475739    AutoLoader.pm            7     <- BEGIN
 117   0 4201691475842    Config.pm              102     -> FETCH
 118   0 4201691475854    Config.pm               11     <- FETCH
 119   0 4201691475870    Config.pm               15     -> FETCH
 120   0 4201691475879    Config.pm                9     <- FETCH
 121   0 4201691475890    Config.pm               10     -> FETCH
 122   0 4201691475898    Config.pm                8     <- FETCH
 123   0 4201691475909    Config.pm               10     -> FETCH
 124   0 4201691475917    Config.pm                8     <- FETCH
 125   0 4201691476012    Kstat.pm                94   <- BEGIN
 126   0 4201691476041    Kstat.pm                29   -> BEGIN
 127   0 4201691476051    vars.pm                  9     -> import
 128   0 4201691476084    vars.pm                 32     <- import
 129   0 4201691476091    Kstat.pm                 7   <- BEGIN
 130   0 4201691476147    DynaLoader.pm           56   -> bootstrap
 131   0 4201691476373    DynaLoader.pm          225     -> dl_load_flags
 132   0 4201691476383    DynaLoader.pm            9     <- dl_load_flags
 133   0 4201691476813    DynaLoader.pm          430   <- bootstrap
 134   0 4201691476837    nicstat                 23 <- BEGIN
 135   0 4201691483648    Std.pm                6811 -> getopts
 136   0 4201691483697    Exporter.pm             49   -> import
 137   0 4201691483737    Exporter.pm             39   <- import
 138   0 4201691483756    Std.pm                  19 <- getopts
 139   0 4201691483780    nicstat                 24 -> find_nets
 140   0 4201691539198    nicstat              55418 <- find_nets
 141   0 4201691539610    nicstat                411 -> fetch_net_data
 142   0 4201691583290    nicstat              43679 <- fetch_net_data
 143   0 4201691583781    nicstat                491 -> print_neat
 144   0 4201691583930    nicstat                149 <- print_neat
 145   0 4201691583996    nicstat                 65 -> print_neat
 146   0 4201691584165    nicstat                169 <- print_neat
 147   0 4201691584174    nicstat                  9 -> print_neat
 148   0 4201691584298    nicstat                124 <- print_neat
 149   0 4201691584308    nicstat                  9 -> print_neat
 150   0 4201691584432    nicstat                124 <- print_neat
 151   0 4201691584473    nicstat                 41 -> print_neat
 152   0 4201691584597    nicstat                123 <- print_neat
 153   0 4201691584607    nicstat                  9 -> print_neat
 154   0 4201691584730    nicstat                123 <- print_neat
 155   0 4201691585091    nicstat                361 -> print_neat
 156   0 4201691585217    nicstat                125 <- print_neat
 157   0 4201691585226    nicstat                  9 -> print_neat
 158   0 4201691585379    nicstat                152 <- print_neat
 159   0 4201691585389    nicstat                  9 -> print_neat
 160   0 4201691585512    nicstat                123 <- print_neat
 161   0 4201691585521    nicstat                  9 -> print_neat
 162   0 4201691585644    nicstat                123 <- print_neat
 163   0 4201691585653    nicstat                  9 -> print_neat
 164   0 4201691585825    nicstat                171 <- print_neat
 165   0 4201691585834    nicstat                  9 -> print_neat
 166   0 4201691585988    nicstat                154 <- print_neat
 167   0 4201691586274    nicstat                285 -> print_neat
 168   0 4201691586434    nicstat                160 <- print_neat
 169   0 4201691586443    nicstat                  9 -> print_neat
 170   0 4201691586567    nicstat                123 <- print_neat
 171   0 4201691586576    nicstat                  9 -> print_neat
 172   0 4201691586731    nicstat                154 <- print_neat
 173   0 4201691586740    nicstat                  8 -> print_neat
 174   0 4201691586892    nicstat                151 <- print_neat
 175   0 4201691586901    nicstat                  9 -> print_neat
 176   0 4201691587025    nicstat                123 <- print_neat
 177   0 4201691587034    nicstat                  9 -> print_neat
 178   0 4201691587157    nicstat                123 <- print_neat
 179   0 4201691590909    Config.pm             3751 -> DESTROY
 180   0 4201691590938    Config.pm               29 <- DESTROY
 181
 182 After initialising Perl libraries and modules, the "nicstat" program ran,
 183 the output matching what was expected from the source.
 184
 185 The DELTA column shows that most time is spent in the find_nets() and
 186 fetch_nets_data() subroutines, with 55.4 ms and 44.7 ms of elapsed
 187 function time respectively. Those particular times were easy to interpret,
 188 since there were no child subroutines called, and the delta spanned
 189 the subroutine entry to its return.
 190
 191 Some times get trickier to comprehend. The 2nd last line with a DELTA time
 192 of 3751 us, means "the time from the print_neat() subroutine completing
 193 to the DESTROY() subroutine starting, took 3751 us.". What is happening
 194 during this time? It is hard to say based on this output - since it isn't
 195 time within a function, rather it is time that Perl spent processing the
 196 main program. Since we have the last function called, we may guess where
 197 the program was at; or we could enhance this script to trace Perl engine
 198 internals as well (and/or syscalls).
 199