cddl/contrib/dtracetoolkit/Examples/sh_flowtime_example.txt

   1 The following are examples of sh_flowtime.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_flowtime.d
   8      C TIME(us)         FILE             DELTA(us) -- NAME
   9      0 3060817866026    func_abc.sh              2 -> func_a
  10      0 3060817866086    func_abc.sh             60   > echo
  11      0 3060818871601    func_abc.sh        1005514   | sleep
  12      0 3060818871639    func_abc.sh             38   -> func_b
  13      0 3060818871684    func_abc.sh             44     > echo
  14      0 3060819881597    func_abc.sh        1009912     | sleep
  15      0 3060819881657    func_abc.sh             60     -> func_c
  16      0 3060819881717    func_abc.sh             60       > echo
  17      0 3060820891613    func_abc.sh        1009896       | sleep
  18      0 3060820891661    func_abc.sh             47     <- func_c
  19      0 3060820891675    func_abc.sh             14   <- func_b
  20      0 3060820891683    func_abc.sh              7 <- func_a
  21    ^C
  22
  23 As each function is entered, the third column is indented by 2 spaces. This
  24 shows which function is calling who - the output above begins by showing that
  25 func_a() began, and then called func_b().
  26
  27 The DELTA(us) column is interpreted as follows,
  28
  29         ->              previous line to the start of this function
  30         <-              previous line to the end of this function
  31         >               previous line to the end of this builtin
  32         |               previous line to the end of this command
  33
  34 And so the above output shows that each sleep command is taking around 1.0
  35 seconds to execute.
  36
  37 If the output looks shuffled, check the CPU "C" and "TIME" columns, and
  38 post sort based on TIME if necessary.
  39
  40 See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
  41
  42
  43
  44 The following traces the firefox start script.
  45
  46 # sh_flowtime.d
  47   C TIME(us)         FILE             DELTA(us) -- NAME
  48   0 3060994282580    firefox                  2 > test
  49   0 3060994286921    firefox               4341 > [
  50   0 3060994286955    firefox                 34 > cd
  51   0 3060994287014    firefox                 58 > [
  52   0 3060994287059    firefox                 45 > [
  53   0 3060994287227    firefox                167 > [
  54   0 3060994293793    firefox                  2 > echo
  55   0 3060994305759    firefox                  2 > echo
  56   0 3060994309613    firefox              22385 > [
  57   0 3060994309665    firefox                 52 > export
  58   0 3060994309691    firefox                 25 -> moz_pis_startstop_scripts
  59   0 3060994309752    firefox                 61   > export
  60   0 3060994310199    firefox                447   > [
  61   0 3060994314462    firefox               4262   -> moz_spc_verbose_echo
  62   0 3060994314484    firefox                 22     > :
  63   0 3060994314497    firefox                 12   <- moz_spc_verbose_echo
  64   0 3060994322101    firefox               7604   > [
  65   0 3060994322134    firefox                 33   -> moz_spc_verbose_echo
  66   0 3060994322147    firefox                 12     > :
  67   0 3060994322155    firefox                  7   <- moz_spc_verbose_echo
  68   0 3060994322501    firefox                345   > [
  69   0 3060994322518    firefox                 17   > [
  70   0 3060994322578    firefox                 59   > [
  71   0 3060994322641    firefox                 62   -> moz_spc_verbose_echo
  72   0 3060994322650    firefox                  9     > :
  73   0 3060994322656    firefox                  6   <- moz_spc_verbose_echo
  74   0 3060994653794    firefox             331137   -> moz_spc_verbose_echo
  75   0 3060994653826    firefox                 32     > :
  76   0 3060994653839    firefox                 12   <- moz_spc_verbose_echo
  77   0 3060994659534    firefox                  2 > [
  78   0 3060994667539    firefox              13699   > [
  79   0 3060994667604    firefox                 65   -> moz_spc_verbose_echo
  80   0 3060994667617    firefox                 13     > :
  81   0 3060994667625    firefox                  8   <- moz_spc_verbose_echo
  82   0 3060994667653    firefox                 27   -> moz_spc_verbose_echo
  83   0 3060994667661    firefox                  7     > :
  84   0 3060994667668    firefox                  6   <- moz_spc_verbose_echo
  85   0 3060994667675    firefox                  7   > .
  86   0 3060994667725    firefox                 49   > [
  87   0 3060994667732    firefox                  6 <- moz_pis_startstop_scripts
  88   0 3060994667853    firefox                121 > [
  89   0 3060994667881    firefox                 27 > [
  90   0 3060994804329    run-mozilla.sh           2 > [
  91   0 3060994804524    run-mozilla.sh         194 > break
  92   0 3060994804560    run-mozilla.sh          36 > [
  93   0 3060994804580    run-mozilla.sh          20 > shift
  94   0 3060994804649    run-mozilla.sh          68 > [
  95   0 3060994804710    run-mozilla.sh          61 > [
  96   0 3060994804747    run-mozilla.sh          36 > [
  97   0 3060994804889    run-mozilla.sh         142 > [
  98   0 3060994804915    run-mozilla.sh          26 > export
  99   0 3060994804952    run-mozilla.sh          36 > [
 100   0 3060994804981    run-mozilla.sh          28 > [
 101   0 3060994805093    run-mozilla.sh         112 > [
 102   0 3060994805116    run-mozilla.sh          22 > export
 103   0 3060994805160    run-mozilla.sh          44 > export
 104   0 3060994805187    run-mozilla.sh          27 > [
 105   0 3060994805215    run-mozilla.sh          27 -> moz_run_program
 106   0 3060994805263    run-mozilla.sh          48   > [
 107   0 3060994805283    run-mozilla.sh          19   -> moz_test_binary
 108   0 3060994805314    run-mozilla.sh          31     > [
 109   0 3060994805346    run-mozilla.sh          31     > [
 110   0 3060994805358    run-mozilla.sh          12     > return
 111   0 3060994805367    run-mozilla.sh           9   <- moz_test_binary
 112   0 3060994805385    run-mozilla.sh          17   > [
 113   0 3060994964498    run-mozilla.sh           2 > type
 114   0 3060995520942    run-mozilla.sh      715556   > [
 115   0 3060995520967    run-mozilla.sh          24   > [
 116   0 3060995520987    run-mozilla.sh          20   > [
 117   0 3061000622172    run-mozilla.sh     5101184   | /usr/lib/firefox/firefox-bin
 118   0 3061000622221    run-mozilla.sh          49   > [
 119   0 3061000622252    run-mozilla.sh          30   > [
 120   0 3061000622266    run-mozilla.sh          14   > [
 121   0 3061000622275    run-mozilla.sh           9 <- moz_run_program
 122   0 3061000623686    firefox            5955805 | /usr/lib/firefox/run-mozilla.sh
 123   0 3061000623793    firefox                106 -> moz_pis_startstop_scripts
 124   0 3061000623864    firefox                 71   > export
 125   0 3061000624108    firefox                244   > [
 126   0 3061000624138    firefox                 30   > [
 127   0 3061000624147    firefox                  8 <- moz_pis_startstop_scripts
 128
 129 Points of latency during startup are visible in the output. For more details,
 130 see Examples/sh_flowinfo_example.txt.
 131