cddl/contrib/dtracetoolkit/Examples/tcl_calldist_example.txt

   1 The following are examples of tcl_calldist.d.
   2
   3 This script traces the elapsed time of Tcl procedures and commands and
   4 prints a report containing distribution plots per function. Here it traces the
   5 example program, Code/Tcl/func_abc.tcl
   6
   7 # tcl_calldist.d
   8 Tracing... Hit Ctrl-C to end.
   9 ^C
  10
  11 Top 10 exclusive elapsed times (us),
  12    PID=16033, cmd, namespace
  13            value  ------------- Distribution ------------- count
  14                1 |                                         0
  15                2 |@@@@@@@@@@@@@                            1
  16                4 |@@@@@@@@@@@@@                            1
  17                8 |                                         0
  18               16 |                                         0
  19               32 |                                         0
  20               64 |                                         0
  21              128 |@@@@@@@@@@@@@                            1
  22              256 |                                         0
  23
  24    PID=16033, cmd, puts
  25            value  ------------- Distribution ------------- count
  26               16 |                                         0
  27               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  28               64 |                                         0
  29              128 |@@@@@@@@@@@@@                            1
  30              256 |                                         0
  31
  32    PID=16033, cmd, tclInit
  33            value  ------------- Distribution ------------- count
  34              128 |                                         0
  35              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  36              512 |                                         0
  37
  38    PID=16033, proc, func_a
  39            value  ------------- Distribution ------------- count
  40              128 |                                         0
  41              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  42              512 |                                         0
  43
  44    PID=16033, proc, func_b
  45            value  ------------- Distribution ------------- count
  46              128 |                                         0
  47              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  48              512 |                                         0
  49
  50    PID=16033, proc, func_c
  51            value  ------------- Distribution ------------- count
  52              128 |                                         0
  53              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  54              512 |                                         0
  55
  56    PID=16033, cmd, file
  57            value  ------------- Distribution ------------- count
  58                2 |                                         0
  59                4 |@@@@@@@@@@@@@                            4
  60                8 |@@@@@@@                                  2
  61               16 |@@@@@@@                                  2
  62               32 |@@@                                      1
  63               64 |@@@@@@@@@@                               3
  64              128 |                                         0
  65
  66    PID=16033, cmd, source
  67            value  ------------- Distribution ------------- count
  68              256 |                                         0
  69              512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  70             1024 |                                         0
  71
  72    PID=16033, cmd, if
  73            value  ------------- Distribution ------------- count
  74                8 |                                         0
  75               16 |@@@@@@@@@@@@@@@@@@@@                     4
  76               32 |@@@@@@@@@@@@@@@                          3
  77               64 |                                         0
  78              128 |                                         0
  79              256 |                                         0
  80              512 |@@@@@                                    1
  81             1024 |                                         0
  82
  83    PID=16033, cmd, after
  84            value  ------------- Distribution ------------- count
  85           262144 |                                         0
  86           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
  87          1048576 |                                         0
  88
  89
  90 Top 10 inclusive elapsed times (us),
  91    PID=16033, cmd, uplevel
  92            value  ------------- Distribution ------------- count
  93              512 |                                         0
  94             1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  95             2048 |                                         0
  96
  97    PID=16033, cmd, tclInit
  98            value  ------------- Distribution ------------- count
  99             1024 |                                         0
 100             2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 101             4096 |                                         0
 102
 103    PID=16033, proc, tclInit
 104            value  ------------- Distribution ------------- count
 105             1024 |                                         0
 106             2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 107             4096 |                                         0
 108
 109    PID=16033, cmd, func_c
 110            value  ------------- Distribution ------------- count
 111           262144 |                                         0
 112           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 113          1048576 |                                         0
 114
 115    PID=16033, proc, func_c
 116            value  ------------- Distribution ------------- count
 117           262144 |                                         0
 118           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 119          1048576 |                                         0
 120
 121    PID=16033, cmd, func_b
 122            value  ------------- Distribution ------------- count
 123           524288 |                                         0
 124          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 125          2097152 |                                         0
 126
 127    PID=16033, proc, func_b
 128            value  ------------- Distribution ------------- count
 129           524288 |                                         0
 130          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 131          2097152 |                                         0
 132
 133    PID=16033, cmd, after
 134            value  ------------- Distribution ------------- count
 135           262144 |                                         0
 136           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
 137          1048576 |                                         0
 138
 139    PID=16033, cmd, func_a
 140            value  ------------- Distribution ------------- count
 141          1048576 |                                         0
 142          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 143          4194304 |                                         0
 144
 145    PID=16033, proc, func_a
 146            value  ------------- Distribution ------------- count
 147          1048576 |                                         0
 148          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 149          4194304 |                                         0
 150
 151 The exclusive function elapsed times show that each func_a took between 256
 152 and 511 microseconds. This time excludes the time spent in any other functions.
 153
 154 The inclusive elapsed times section shows that each func_a spent
 155 took between 2.1 and 4.2 seconds. This time also includes the time spent in
 156 any other commands or procedures called by func_a.
 157
 158 These elapsed times are the absolute time from when the function began to
 159 when it completed - which includes off-CPU time due to other system events
 160 such as I/O, scheduling, interrupts, etc.
 161
 162 Elapsed times are useful for identifying where latencies are.
 163 See Notes/ALLelapsed_notes.txt for more details. Also see
 164 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
 165 detailed explanation of exclusive vs inclusive function time.
 166