1 The following are examples of tcl_calldist.d.
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
8 Tracing... Hit Ctrl-C to end.
11 Top 10 exclusive elapsed times (us),
12 PID=16033, cmd, namespace
13 value ------------- Distribution ------------- count
25 value ------------- Distribution ------------- count
27 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
32 PID=16033, cmd, tclInit
33 value ------------- Distribution ------------- count
35 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
38 PID=16033, proc, func_a
39 value ------------- Distribution ------------- count
41 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
44 PID=16033, proc, func_b
45 value ------------- Distribution ------------- count
47 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
50 PID=16033, proc, func_c
51 value ------------- Distribution ------------- count
53 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
57 value ------------- Distribution ------------- count
66 PID=16033, cmd, source
67 value ------------- Distribution ------------- count
69 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
73 value ------------- Distribution ------------- count
75 16 |@@@@@@@@@@@@@@@@@@@@ 4
84 value ------------- Distribution ------------- count
86 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
90 Top 10 inclusive elapsed times (us),
91 PID=16033, cmd, uplevel
92 value ------------- Distribution ------------- count
94 1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
97 PID=16033, cmd, tclInit
98 value ------------- Distribution ------------- count
100 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
103 PID=16033, proc, tclInit
104 value ------------- Distribution ------------- count
106 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
109 PID=16033, cmd, func_c
110 value ------------- Distribution ------------- count
112 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
115 PID=16033, proc, func_c
116 value ------------- Distribution ------------- count
118 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
121 PID=16033, cmd, func_b
122 value ------------- Distribution ------------- count
124 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
127 PID=16033, proc, func_b
128 value ------------- Distribution ------------- count
130 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
133 PID=16033, cmd, after
134 value ------------- Distribution ------------- count
136 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
139 PID=16033, cmd, func_a
140 value ------------- Distribution ------------- count
142 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
145 PID=16033, proc, func_a
146 value ------------- Distribution ------------- count
148 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
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.
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.
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.
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.