cddl/contrib/dtracetoolkit/Examples/sh_flowinfo_example.txt

   1 The following are examples of sh_flowinfo.d.
   2
   3 This is a simple script to trace the flow of Bourne shell functions,
   4 builtins and external commands. Here it traces the example program,
   5 Code/Shell/func_abc.sh.
   6
   7    # sh_flowinfo.d
   8      C    PID  DELTA(us)              FILE:LINE TYPE     -- NAME
   9      0  19634          2       func_abc.sh:23   func     -> func_a
  10      0  19634         24       func_abc.sh:18   builtin    -> echo
  11      0  19634         41       func_abc.sh:-    builtin    <- echo
  12      0  19634       5873       func_abc.sh:19   cmd        -> sleep
  13      0  19634     999373       func_abc.sh:-    cmd        <- sleep
  14      0  19634         39       func_abc.sh:20   func       -> func_b
  15      0  19634         22       func_abc.sh:11   builtin      -> echo
  16      0  19634         40       func_abc.sh:-    builtin      <- echo
  17      0  19634       4661       func_abc.sh:12   cmd          -> sleep
  18      0  19634    1005349       func_abc.sh:-    cmd          <- sleep
  19      0  19634         49       func_abc.sh:13   func         -> func_c
  20      0  19634         22       func_abc.sh:5    builtin        -> echo
  21      0  19634         38       func_abc.sh:-    builtin        <- echo
  22      0  19634       4949       func_abc.sh:6    cmd            -> sleep
  23      0  19634    1004817       func_abc.sh:-    cmd            <- sleep
  24      0  19634         36       func_abc.sh:-    func         <- func_c
  25      0  19634         14       func_abc.sh:-    func       <- func_b
  26      0  19634          8       func_abc.sh:-    func     <- func_a
  27
  28 As each function is entered, the third column is indented by 2 spaces. This
  29 shows which function is calling who - the output abovebegins by showing that
  30 func_a() began, and then called func_b().
  31
  32 The DELTA(us) column shows time from that line to the previous line, and
  33 so can be a bit tricky to read. For example, the fifth line of data output
  34 (skipping the header) reads as "the time from the command sleep beginning
  35 to ending was 999373 us, or 1.0 seconds".
  36
  37 The LINE column shows the line in the file what was being executed. Refer
  38 to the source program to see what this line refers to.
  39
  40 If the output looks shuffled, check the CPU "C" column - if it changes,
  41 then the output is probably shuffled. See Notes/ALLsnoop_notes.txt for
  42 details and suggested workarounds.
  43
  44 See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
  45
  46
  47 The following traces the firefox startup script.
  48
  49 # sh_flowinfo.d
  50   C    PID  DELTA(us)              FILE:LINE TYPE     -- NAME
  51   0 156789          1           firefox:-    subsh    -> pid 156790
  52   0 156789         20           firefox:-    subsh    <- = 0
  53   0 156789      31651           firefox:-    subsh    -> pid 156791
  54   0 156789         20           firefox:-    subsh    <- = 0
  55   0 156789      10502           firefox:109  builtin  -> test
  56   0 156789         59           firefox:-    builtin  <- test
  57   0 156789       3804           firefox:-    subsh    -> pid 156792
  58   0 156789         21           firefox:-    subsh    <- = 0
  59   0 156789      22029           firefox:114  builtin  -> [
  60   0 156789         57           firefox:-    builtin  <- [
  61   0 156789      90910           firefox:-    subsh    -> pid 156793
  62   0 156789         22           firefox:-    subsh    <- = 0
  63   0 156789     159492           firefox:-    subsh    -> pid 156794
  64   0 156789         22           firefox:-    subsh    <- = 0
  65   0 156789        127           firefox:116  builtin  -> cd
  66   0 156789         54           firefox:-    builtin  <- cd
  67   0 156789     209757           firefox:-    subsh    -> pid 156795
  68   0 156789         23           firefox:-    subsh    <- = 0
  69   0 156795     206160           firefox:-    subsh    -> pid 156796
  70   0 156795          9           firefox:-    subsh    <- = 0
  71   0 156789      12115           firefox:118  builtin  -> [
  72   0 156789         61           firefox:-    builtin  <- [
  73   0 156789     200529           firefox:-    subsh    -> pid 156797
  74   0 156789         24           firefox:-    subsh    <- = 0
  75   0 156789        136           firefox:123  builtin  -> [
  76   0 156789         58           firefox:-    builtin  <- [
  77   0 156789         21           firefox:124  builtin  -> cd
  78   0 156789         19           firefox:-    builtin  <- cd
  79   0 156798        175           firefox:1    builtin  -> pwd
  80   0 156798         65           firefox:-    builtin  <- pwd
  81   0 156789     108835           firefox:-    subsh    -> pid 156798
  82   0 156789         18           firefox:-    subsh    <- = 0
  83   0 156789        119           firefox:128  builtin  -> break
  84   0 156789         15           firefox:-    builtin  <- break
  85   0 156789         21           firefox:131  builtin  -> cd
  86   0 156789         26           firefox:-    builtin  <- cd
  87   0 156789         61           firefox:133  builtin  -> [
  88   0 156789          9           firefox:-    builtin  <- [
  89   0 156789      73508           firefox:147  builtin  -> [
  90   0 156789         25           firefox:-    builtin  <- [
  91   0 156800        184           firefox:1    builtin  -> echo
  92   0 156800        175           firefox:-    builtin  <- echo
  93   0 156789      15966           firefox:-    subsh    -> pid 156799
  94   0 156789         22           firefox:-    subsh    <- = 0
  95   0 156799      12091           firefox:-    subsh    -> pid 156800
  96   0 156799         10           firefox:-    subsh    <- = 0
  97   0 156802        178           firefox:1    builtin  -> echo
  98   0 156802        167           firefox:-    builtin  <- echo
  99   0 156789      13822           firefox:-    subsh    -> pid 156801
 100   0 156789         18           firefox:-    subsh    <- = 0
 101   0 156801      81683           firefox:-    subsh    -> pid 156802
 102   0 156801         21           firefox:-    subsh    <- = 0
 103   0 156789      78324           firefox:158  builtin  -> [
 104   0 156789         37           firefox:-    builtin  <- [
 105   0 156789         54           firefox:194  builtin  -> export
 106   0 156789          9           firefox:-    builtin  <- export
 107   0 156789         26           firefox:197  func     -> moz_pis_startstop_scripts
 108   0 156789         61           firefox:62   builtin    -> export
 109   0 156789          9           firefox:-    builtin    <- export
 110   0 156789        413           firefox:67   builtin    -> [
 111   0 156789         34           firefox:-    builtin    <- [
 112   0 156789         40           firefox:69   builtin    -> .
 113   0 156789      20833           firefox:18   func         -> moz_spc_verbose_echo
 114   0 156789         26           firefox:15   builtin        -> :
 115   0 156789         16           firefox:-    builtin        <- :
 116   0 156789         15           firefox:-    func         <- moz_spc_verbose_echo
 117   0 156789     105106           firefox:-    subsh        -> pid 156803
 118   0 156789         22           firefox:-    subsh        <- = 0
 119   0 156789        129           firefox:19   builtin      -> [
 120   0 156789         17           firefox:-    builtin      <- [
 121   0 156789         33           firefox:20   func         -> moz_spc_verbose_echo
 122   0 156789         14           firefox:15   builtin        -> :
 123   0 156789          7           firefox:-    builtin        <- :
 124   0 156789          9           firefox:-    func         <- moz_spc_verbose_echo
 125   0 156789         21           firefox:23   builtin      -> [
 126   0 156789          8           firefox:-    builtin      <- [
 127   0 156789         16           firefox:26   builtin      -> [
 128   0 156789          8           firefox:-    builtin      <- [
 129   0 156789         24           firefox:29   builtin      -> [
 130   0 156789         43           firefox:-    builtin      <- [
 131   0 156789         77           firefox:36   func         -> moz_spc_verbose_echo
 132   0 156789          9           firefox:15   builtin        -> :
 133   0 156789          8           firefox:-    builtin        <- :
 134   0 156789          8           firefox:-    func         <- moz_spc_verbose_echo
 135   0 156789     158947           firefox:-    subsh        -> pid 156804
 136   0 156789         22           firefox:-    subsh        <- = 0
 137   0 156789     210112           firefox:-    subsh        -> pid 156805
 138   0 156789         22           firefox:-    subsh        <- = 0
 139   0 156805     205500           firefox:-    subsh    -> pid 156806
 140   0 156805         10           firefox:-    subsh    <- = 0
 141   0 156805     200987           firefox:-    subsh    -> pid 156807
 142   0 156805         20           firefox:-    subsh    <- = 0
 143   0 156789     363564           firefox:40   func         -> moz_spc_verbose_echo
 144   0 156789         26           firefox:15   builtin        -> :
 145   0 156789         17           firefox:-    builtin        <- :
 146   0 156789         15           firefox:-    func         <- moz_spc_verbose_echo
 147   0 156809        234           firefox:1    builtin  -> [
 148   0 156809         70           firefox:-    builtin  <- [
 149   0 156789      46950           firefox:-    subsh        -> pid 156808
 150   0 156789         22           firefox:-    subsh        <- = 0
 151   0 156808      42371           firefox:-    subsh    -> pid 156809
 152   0 156808         10           firefox:-    subsh    <- = 0
 153   0 156789      27278           firefox:43   builtin      -> [
 154   0 156789         26           firefox:-    builtin      <- [
 155   0 156789         62           firefox:44   func         -> moz_spc_verbose_echo
 156   0 156789         15           firefox:15   builtin        -> :
 157   0 156789          8           firefox:-    builtin        <- :
 158   0 156789         10           firefox:-    func         <- moz_spc_verbose_echo
 159   0 156789         30           firefox:67   func         -> moz_spc_verbose_echo
 160   0 156789          9           firefox:15   builtin        -> :
 161   0 156789          8           firefox:-    builtin        <- :
 162   0 156789          7           firefox:-    func         <- moz_spc_verbose_echo
 163   0 156789          8           firefox:-    builtin    <- .
 164   0 156789         28           firefox:67   builtin    -> [
 165   0 156789         31           firefox:-    builtin    <- [
 166   0 156789          8           firefox:-    func     <- moz_pis_startstop_scripts
 167   0 156789         97           firefox:199  builtin  -> [
 168   0 156789         35           firefox:-    builtin  <- [
 169   0 156789         29           firefox:205  builtin  -> [
 170   0 156789          9           firefox:-    builtin  <- [
 171   0 156789      72519           firefox:209  cmd      -> /usr/lib/firefox/run-mozilla.sh
 172   0 156810          1    run-mozilla.sh:-    subsh    -> pid 156811
 173   0 156810         15    run-mozilla.sh:-    subsh    <- = 0
 174   0 156810     129474    run-mozilla.sh:-    subsh    -> pid 156812
 175   0 156810         24    run-mozilla.sh:-    subsh    <- = 0
 176   0 156810        743    run-mozilla.sh:258  builtin  -> [
 177   0 156810         28    run-mozilla.sh:-    builtin  <- [
 178   0 156810        212    run-mozilla.sh:275  builtin  -> break
 179   0 156810         10    run-mozilla.sh:-    builtin  <- break
 180   0 156810         31    run-mozilla.sh:283  builtin  -> [
 181   0 156810         10    run-mozilla.sh:-    builtin  <- [
 182   0 156810         16    run-mozilla.sh:286  builtin  -> shift
 183   0 156810          9    run-mozilla.sh:-    builtin  <- shift
 184   0 156810         55    run-mozilla.sh:291  builtin  -> [
 185   0 156810          9    run-mozilla.sh:-    builtin  <- [
 186   0 156810         36    run-mozilla.sh:317  builtin  -> [
 187   0 156810         34    run-mozilla.sh:-    builtin  <- [
 188   0 156810         37    run-mozilla.sh:327  builtin  -> [
 189   0 156810          9    run-mozilla.sh:-    builtin  <- [
 190   0 156810        142    run-mozilla.sh:362  builtin  -> [
 191   0 156810          9    run-mozilla.sh:-    builtin  <- [
 192   0 156810         26    run-mozilla.sh:366  builtin  -> export
 193   0 156810          9    run-mozilla.sh:-    builtin  <- export
 194   0 156810         37    run-mozilla.sh:369  builtin  -> [
 195   0 156810          9    run-mozilla.sh:-    builtin  <- [
 196   0 156810         18    run-mozilla.sh:371  builtin  -> [
 197   0 156810         19    run-mozilla.sh:-    builtin  <- [
 198   0 156810        112    run-mozilla.sh:379  builtin  -> [
 199   0 156810         10    run-mozilla.sh:-    builtin  <- [
 200   0 156810         23    run-mozilla.sh:418  builtin  -> export
 201   0 156810          9    run-mozilla.sh:-    builtin  <- export
 202   0 156810         45    run-mozilla.sh:419  builtin  -> export
 203   0 156810         10    run-mozilla.sh:-    builtin  <- export
 204   0 156810         27    run-mozilla.sh:421  builtin  -> [
 205   0 156810          9    run-mozilla.sh:-    builtin  <- [
 206   0 156810         29    run-mozilla.sh:425  func     -> moz_run_program
 207   0 156810         32    run-mozilla.sh:137  builtin    -> [
 208   0 156810         25    run-mozilla.sh:-    builtin    <- [
 209   0 156810         20    run-mozilla.sh:145  func       -> moz_test_binary
 210   0 156810         17    run-mozilla.sh:97   builtin      -> [
 211   0 156810         23    run-mozilla.sh:-    builtin      <- [
 212   0 156810         15    run-mozilla.sh:99   builtin      -> [
 213   0 156810         26    run-mozilla.sh:-    builtin      <- [
 214   0 156810         13    run-mozilla.sh:101  builtin      -> return
 215   0 156810          9    run-mozilla.sh:-    builtin      <- return
 216   0 156810         11    run-mozilla.sh:-    func       <- moz_test_binary
 217   0 156810         18    run-mozilla.sh:146  builtin    -> [
 218   0 156810          9    run-mozilla.sh:-    builtin    <- [
 219   0 156814        185    run-mozilla.sh:1    builtin  -> type
 220   0 156814     118188    run-mozilla.sh:-    builtin  <- type
 221   0 156810     167284    run-mozilla.sh:-    subsh      -> pid 156813
 222   0 156810         23    run-mozilla.sh:-    subsh      <- = 0
 223   0 156813     162135    run-mozilla.sh:-    subsh    -> pid 156814
 224   0 156813         12    run-mozilla.sh:-    subsh    <- = 0
 225   0 156813     200125    run-mozilla.sh:-    subsh    -> pid 156815
 226   0 156813         22    run-mozilla.sh:-    subsh    <- = 0
 227   0 156810     203465    run-mozilla.sh:152  builtin    -> [
 228   0 156810         51    run-mozilla.sh:-    builtin    <- [
 229   0 156810         21    run-mozilla.sh:156  builtin    -> [
 230   0 156810          9    run-mozilla.sh:-    builtin    <- [
 231   0 156810         15    run-mozilla.sh:159  builtin    -> [
 232   0 156810         14    run-mozilla.sh:-    builtin    <- [
 233   0 156810      65752    run-mozilla.sh:-    subsh      -> pid 156816
 234   0 156810         24    run-mozilla.sh:-    subsh      <- = 0
 235   0 156816     251788    run-mozilla.sh:-    subsh    -> pid 156817
 236   0 156816         22    run-mozilla.sh:-    subsh    <- = 0
 237   0 156810     299677    run-mozilla.sh:167  cmd        -> /usr/lib/firefox/firefox-bin
 238   0 156810    5124906    run-mozilla.sh:-    cmd        <- /usr/lib/firefox/firefox-bin
 239   0 156789    5993798           firefox:-    cmd      <- /usr/lib/firefox/run-mozilla.sh
 240
 241 Now latencies can investigated by line number.
 242