The following are examples of tcl_calldist.d.
This script traces the elapsed time of Tcl procedures and commands and
prints a report containing distribution plots per function. Here it traces the
example program, Code/Tcl/func_abc.tcl
Tracing... Hit Ctrl-C to end.
^C
Top 10 exclusive elapsed times (us),
PID=16033, cmd, namespace
value ------------- Distribution ------------- count
1 | 0
2 |@@@@@@@@@@@@@ 1
4 |@@@@@@@@@@@@@ 1
8 | 0
16 | 0
32 | 0
64 | 0
128 |@@@@@@@@@@@@@ 1
256 | 0
PID=16033, cmd, puts
value ------------- Distribution ------------- count
16 | 0
32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
64 | 0
128 |@@@@@@@@@@@@@ 1
256 | 0
PID=16033, cmd, tclInit
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
512 | 0
PID=16033, proc, func_a
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
512 | 0
PID=16033, proc, func_b
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
512 | 0
PID=16033, proc, func_c
value ------------- Distribution ------------- count
128 | 0
256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
512 | 0
PID=16033, cmd, file
value ------------- Distribution ------------- count
2 | 0
4 |@@@@@@@@@@@@@ 4
8 |@@@@@@@ 2
16 |@@@@@@@ 2
32 |@@@ 1
64 |@@@@@@@@@@ 3
128 | 0
PID=16033, cmd, source
value ------------- Distribution ------------- count
256 | 0
512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1024 | 0
PID=16033, cmd, if
value ------------- Distribution ------------- count
8 | 0
16 |@@@@@@@@@@@@@@@@@@@@ 4
32 |@@@@@@@@@@@@@@@ 3
64 | 0
128 | 0
256 | 0
512 |@@@@@ 1
1024 | 0
PID=16033, cmd, after
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
1048576 | 0
Top 10 inclusive elapsed times (us),
PID=16033, cmd, uplevel
value ------------- Distribution ------------- count
512 | 0
1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
2048 | 0
PID=16033, cmd, tclInit
value ------------- Distribution ------------- count
1024 | 0
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4096 | 0
PID=16033, proc, tclInit
value ------------- Distribution ------------- count
1024 | 0
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4096 | 0
PID=16033, cmd, func_c
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
PID=16033, proc, func_c
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1048576 | 0
PID=16033, cmd, func_b
value ------------- Distribution ------------- count
524288 | 0
1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
2097152 | 0
PID=16033, proc, func_b
value ------------- Distribution ------------- count
524288 | 0
1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
2097152 | 0
PID=16033, cmd, after
value ------------- Distribution ------------- count
262144 | 0
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
1048576 | 0
PID=16033, cmd, func_a
value ------------- Distribution ------------- count
1048576 | 0
2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4194304 | 0
PID=16033, proc, func_a
value ------------- Distribution ------------- count
1048576 | 0
2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
4194304 | 0
The exclusive function elapsed times show that each func_a took between 256
and 511 microseconds. This time excludes the time spent in any other functions.
The inclusive elapsed times section shows that each func_a spent
took between 2.1 and 4.2 seconds. This time also includes the time spent in
any other commands or procedures called by func_a.
These elapsed times are the absolute time from when the function began to
when it completed - which includes off-CPU time due to other system events
such as I/O, scheduling, interrupts, etc.
Elapsed times are useful for identifying where latencies are.
See Notes/ALLelapsed_notes.txt for more details. Also see
detailed explanation of exclusive vs inclusive function time.