cddl/contrib/dtracetoolkit/Examples/sh_cpudist_example.txt

   1 The following are examples of sh_cpudist.d.
   2
   3 This script traces the on-CPU time of Bourne shell functions and
   4 prints a report containing distribution plots per function. Here it
   5 traces the example program, Code/Shell/func_slow.sh.
   6
   7    # sh_cpudist.d
   8    Tracing... Hit Ctrl-C to end.
   9    ^C
  10
  11    On-CPU times (us),
  12
  13       func_slow.sh, builtin, echo
  14               value  ------------- Distribution ------------- count
  15                   8 |                                         0
  16                  16 |@@@@@@@@@@@@@                            1
  17                  32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  18                  64 |                                         0
  19
  20       func_slow.sh, builtin, [
  21               value  ------------- Distribution ------------- count
  22                   0 |                                         0
  23                   1 |                                         1
  24                   2 |                                         1
  25                   4 |@                                        22
  26                   8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   575
  27                  16 |                                         2
  28                  32 |                                         0
  29                  64 |                                         2
  30                 128 |                                         0
  31
  32    Exclusive function on-CPU times (us),
  33
  34       func_slow.sh, func, func_a
  35               value  ------------- Distribution ------------- count
  36               65536 |                                         0
  37              131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  38              262144 |                                         0
  39
  40       func_slow.sh, func, func_b
  41               value  ------------- Distribution ------------- count
  42              262144 |                                         0
  43              524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  44             1048576 |                                         0
  45
  46       func_slow.sh, func, func_c
  47               value  ------------- Distribution ------------- count
  48              524288 |                                         0
  49             1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  50             2097152 |                                         0
  51
  52    Inclusive function on-CPU times (us),
  53
  54       func_slow.sh, func, func_b
  55               value  ------------- Distribution ------------- count
  56              524288 |                                         0
  57             1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  58             2097152 |                                         0
  59
  60       func_slow.sh, func, func_c
  61               value  ------------- Distribution ------------- count
  62              524288 |                                         0
  63             1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  64             2097152 |                                         0
  65
  66       func_slow.sh, func, func_a
  67               value  ------------- Distribution ------------- count
  68             1048576 |                                         0
  69             2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  70             4194304 |                                         0
  71
  72 The on-CPU times should that the "[" builtin (test) usually took between
  73 8 and 15 microseconds to execute, and was called over 500 times.
  74
  75 The exclusive function on-CPU times show that func_a() spent between
  76 131 ms and 262 ms on-CPU.
  77
  78 The inclusive function on-CPU times show that both func_b() and func_c()
  79 spent between 1.0 and 2.1 seconds on-CPU, and func_a() spent between 2.1
  80 and 4.2 seconds on-CPU. This inclusive time includes the time spent in other
  81 functions called, and since func_a() called func_b() which called func_c(),
  82 these times make sense.
  83
  84 These on-CPU times are the time the thread spent running on a CPU, from when
  85 the function began to when it completed. This does not include time
  86 spent off-CPU time such as sleeping for I/O or waiting for scheduling.
  87
  88 On-CPU times are useful for showing who is causing the CPUs to be busy.
  89 See Notes/ALLoncpu_notes.txt for more details. Also see
  90 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  91 detailed explanation of exclusive vs inclusive function time.
  92