cddl/contrib/dtracetoolkit/Examples/sh_cputime_example.txt

   1 The following are examples of sh_cputime.d.
   2
   3 This script traces the on-CPU time of Bourne shell functions and
   4 prints a report. Here it traces the example program, Code/Shell/func_slow.sh.
   5
   6    # sh_cputime.d
   7    Tracing... Hit Ctrl-C to end.
   8    ^C
   9
  10    Counts,
  11       FILE                 TYPE       NAME                                COUNT
  12       func_slow.sh         func       func_a                                  1
  13       func_slow.sh         func       func_b                                  1
  14       func_slow.sh         func       func_c                                  1
  15       func_slow.sh         builtin    echo                                    3
  16       func_slow.sh         builtin    [                                     603
  17       -                    total      -                                     609
  18
  19    On-CPU times (us),
  20       FILE                 TYPE       NAME                                TOTAL
  21       func_slow.sh         builtin    echo                                  162
  22       func_slow.sh         builtin    [                                    6279
  23       -                    total      -                                    6441
  24
  25    Exclusive function on-CPU times (us),
  26       FILE                 TYPE       NAME                                TOTAL
  27       func_slow.sh         func       func_a                             269465
  28       func_slow.sh         func       func_b                             670372
  29       func_slow.sh         func       func_c                            1259073
  30       -                    total      -                                 2198911
  31
  32    Inclusive function on-CPU times (us),
  33       FILE                 TYPE       NAME                                TOTAL
  34       func_slow.sh         func       func_c                            1262209
  35       func_slow.sh         func       func_b                            1934839
  36       func_slow.sh         func       func_a                            2205352
  37
  38 In total, three functions were called, one builtin and one command.
  39
  40 The exclusive function on-CPU times show that func_a() spent around 268.4 ms
  41 on-CPU, func_b() spent 670.3 ms, and func_c() spent 1259 ms. This exclusive
  42 times excludes time spent in other functions.
  43
  44 The inclusive function on-CPU times show that func_c() spent around 1.3
  45 seconds on-CPU, func_b() spent around 1.9 seconds, and func_a() spent around
  46 2.2 seconds. This inclusive time includes the time spent in other functions
  47 called, and since func_a() called func_b() which called func_c(), these
  48 times make sense.
  49
  50 These on-CPU times are the time the thread spent running on a CPU, from when
  51 the function began to when it completed. This does not include time
  52 spent off-CPU time such as sleeping for I/O or waiting for scheduling.
  53
  54 On-CPU times are useful for showing who is causing the CPUs to be busy.
  55 See Notes/ALLoncpu_notes.txt for more details. Also see
  56 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  57 detailed explanation of exclusive vs inclusive function time.
  58
  59 If you study the func_slow.sh program alongside the above output, the numbers
  60 should make sense.
  61
  62
  63
  64 The following traced the firefox start script.
  65
  66 # sh_cputime.d
  67 Tracing... Hit Ctrl-C to end.
  68 ^C
  69
  70 Counts,
  71    FILE                 TYPE       NAME                                COUNT
  72    firefox              builtin    break                                   1
  73    firefox              builtin    pwd                                     1
  74    firefox              builtin    test                                    1
  75    firefox              cmd        run-mozilla.sh                          1
  76    run-mozilla.sh       builtin    break                                   1
  77    run-mozilla.sh       builtin    return                                  1
  78    run-mozilla.sh       builtin    shift                                   1
  79    run-mozilla.sh       builtin    type                                    1
  80    run-mozilla.sh       cmd        firefox-bin                             1
  81    run-mozilla.sh       func       moz_run_program                         1
  82    run-mozilla.sh       func       moz_test_binary                         1
  83    firefox              builtin    echo                                    2
  84    firefox              func       moz_pis_startstop_scripts               2
  85    firefox              builtin    cd                                      3
  86    firefox              builtin    export                                  3
  87    run-mozilla.sh       builtin    export                                  3
  88    firefox              builtin    :                                       6
  89    firefox              func       moz_spc_verbose_echo                    6
  90    firefox              builtin    [                                      18
  91    run-mozilla.sh       builtin    [                                      20
  92    -                    total      -                                     103
  93
  94 On-CPU times (us),
  95    FILE                 TYPE       NAME                                TOTAL
  96    run-mozilla.sh       builtin    return                                  0
  97    run-mozilla.sh       builtin    shift                                   0
  98    run-mozilla.sh       builtin    break                                   1
  99    firefox              builtin    break                                   2
 100    run-mozilla.sh       builtin    export                                  4
 101    firefox              builtin    export                                  7
 102    firefox              builtin    :                                       9
 103    firefox              builtin    test                                   35
 104    firefox              builtin    pwd                                    49
 105    firefox              builtin    cd                                     64
 106    run-mozilla.sh       builtin    [                                     176
 107    firefox              builtin    echo                                  309
 108    firefox              builtin    [                                     357
 109    run-mozilla.sh       builtin    type                                  475
 110    firefox              cmd        run-mozilla.sh                      17090
 111    run-mozilla.sh       cmd        firefox-bin                       1932333
 112    -                    total      -                                 1950979
 113
 114 Exclusive function on-CPU times (us),
 115    FILE                 TYPE       NAME                                TOTAL
 116    run-mozilla.sh       func       moz_test_binary                        21
 117    firefox              func       moz_spc_verbose_echo                   22
 118    run-mozilla.sh       func       moz_run_program                      9098
 119    firefox              func       moz_pis_startstop_scripts           12960
 120    -                    total      -                                   22103
 121
 122 Inclusive function on-CPU times (us),
 123    FILE                 TYPE       NAME                                TOTAL
 124    firefox              func       moz_spc_verbose_echo                   31
 125    run-mozilla.sh       func       moz_test_binary                        56
 126    run-mozilla.sh       func       moz_run_program                      9243
 127    firefox              func       moz_pis_startstop_scripts           13133
 128
 129 The output showed that the most CPU time was spent in the firefox-bin command,
 130 taking 1.9 seconds of on-CPU time.
 131