Home | History | Annotate | Line # | Download | only in Examples
      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 
    243