cddl/contrib/dtracetoolkit/Examples/sh_calltime_example.txt

   1 The following are examples of sh_calltime.d.
   2
   3 This script traces the elapsed time of Bourne shell functions and
   4 prints a report. Here it traces the example program, Code/Shell/func_abc.sh.
   5
   6    # sh_calltime.d
   7    Tracing... Hit Ctrl-C to end.
   8    ^C
   9
  10    Counts,
  11       FILE                 TYPE       NAME                                COUNT
  12       func_abc.sh          func       func_a                                  1
  13       func_abc.sh          func       func_b                                  1
  14       func_abc.sh          func       func_c                                  1
  15       func_abc.sh          builtin    echo                                    3
  16       func_abc.sh          cmd        sleep                                   3
  17       -                    total      -                                       9
  18
  19    Elapsed times (us),
  20       FILE                 TYPE       NAME                                TOTAL
  21       func_abc.sh          builtin    echo                                  108
  22       func_abc.sh          cmd        sleep                             3023760
  23       -                    total      -                                 3023868
  24
  25    Exclusive function elapsed times (us),
  26       FILE                 TYPE       NAME                                TOTAL
  27       func_abc.sh          func       func_b                               2629
  28       func_abc.sh          func       func_c                               2822
  29       func_abc.sh          func       func_a                               3249
  30       -                    total      -                                    8702
  31
  32    Inclusive function elapsed times (us),
  33       FILE                 TYPE       NAME                                TOTAL
  34       func_abc.sh          func       func_c                            1009659
  35       func_abc.sh          func       func_b                            2020077
  36       func_abc.sh          func       func_a                            3032571
  37
  38 In total, three functions were called, one builtin and one command.
  39
  40 The elapsed times show that 3.0 seconds was spent in the sleep command,
  41 which is what would be expected based on the script.
  42
  43 The exclusive function elapsed times show that each function spent around
  44 2.7 milliseconds of time processing code - while not in other functions.
  45
  46 The inclusive function elapsed times show that func_a() took around 3.0
  47 seconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0.
  48 The inclusive time includes the time spent in other calls, and since
  49 func_a() called func_b() which called func_c(), and they all call "sleep 1",
  50 these times make sense.
  51
  52 These elapsed times are the absolute time from when the function began to
  53 when it completed - which includes off-CPU time due to other system events
  54 such as I/O, scheduling, interrupts, etc. In particular, for this case it has
  55 included the time waiting for the sleep commands.
  56
  57 Elapsed times are useful for identifying where latencies are.
  58 See Notes/ALLelapsed_notes.txt for more details. Also see
  59 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  60 detailed explanation of exclusive vs inclusive function time.
  61
  62 If you study the func_abc.sh program alongside the above output, the numbers
  63 should make sense.
  64
  65
  66
  67 The following traces the firefox start script.
  68
  69 # sh_calltime.d
  70 Tracing... Hit Ctrl-C to end.
  71 ^C
  72
  73 Counts,
  74    FILE                 TYPE       NAME                                COUNT
  75    firefox              builtin    break                                   1
  76    firefox              builtin    pwd                                     1
  77    firefox              builtin    test                                    1
  78    firefox              cmd        /usr/lib/firefox/run-mozilla.sh         1
  79    run-mozilla.sh       builtin    break                                   1
  80    run-mozilla.sh       builtin    return                                  1
  81    run-mozilla.sh       builtin    shift                                   1
  82    run-mozilla.sh       builtin    type                                    1
  83    run-mozilla.sh       cmd        /usr/lib/firefox/firefox-bin            1
  84    run-mozilla.sh       func       moz_run_program                         1
  85    run-mozilla.sh       func       moz_test_binary                         1
  86    firefox              builtin    echo                                    2
  87    firefox              func       moz_pis_startstop_scripts               2
  88    firefox              builtin    cd                                      3
  89    firefox              builtin    export                                  3
  90    run-mozilla.sh       builtin    export                                  3
  91    firefox              builtin    :                                       6
  92    firefox              func       moz_spc_verbose_echo                    6
  93    firefox              builtin    [                                      18
  94    run-mozilla.sh       builtin    [                                      20
  95    -                    total      -                                     103
  96
  97 Elapsed times (us),
  98    FILE                 TYPE       NAME                                TOTAL
  99    run-mozilla.sh       builtin    return                                  1
 100    run-mozilla.sh       builtin    shift                                   1
 101    run-mozilla.sh       builtin    break                                   2
 102    firefox              builtin    break                                   4
 103    run-mozilla.sh       builtin    export                                  6
 104    firefox              builtin    export                                 10
 105    firefox              builtin    :                                      15
 106    firefox              builtin    pwd                                    50
 107    firefox              builtin    cd                                     72
 108    run-mozilla.sh       builtin    [                                     210
 109    firefox              builtin    echo                                  323
 110    firefox              builtin    [                                     480
 111    run-mozilla.sh       builtin    type                                  486
 112    firefox              builtin    test                                15330
 113    run-mozilla.sh       cmd        /usr/lib/firefox/firefox-bin      8941269
 114    firefox              cmd        /usr/lib/firefox/run-mozilla.sh   9384335
 115    -                    total      -                                18342766
 116
 117 Exclusive function elapsed times (us),
 118    FILE                 TYPE       NAME                                TOTAL
 119    run-mozilla.sh       func       moz_test_binary                        54
 120    firefox              func       moz_spc_verbose_echo                  136
 121    firefox              func       moz_pis_startstop_scripts          230221
 122    run-mozilla.sh       func       moz_run_program                    402343
 123    -                    total      -                                  632756
 124
 125 Inclusive function elapsed times (us),
 126    FILE                 TYPE       NAME                                TOTAL
 127    run-mozilla.sh       func       moz_test_binary                        91
 128    firefox              func       moz_spc_verbose_echo                  151
 129    firefox              func       moz_pis_startstop_scripts          230587
 130    run-mozilla.sh       func       moz_run_program                   9343826
 131
 132
 133
 134 The output showed that the most inclusive function elapsed time was in
 135 moz_run_program() at 9.3 seconds, which comes as little suprise since
 136 I let firefox run for several seconds before closing it. That same duration
 137 explains the large command times in the elapsed times report.
 138
 139 Of more interest are the exclusive function elapsed times, where
 140 moz_pis_startstop_scripts() was the slowest at 230 ms. Other areas of the
 141 report are also useful to sanity check your software - should it be calling
 142 these things? Especially if there are any commands called that can be
 143 builtins instead.
 144