The following are examples of tcl_calltime.d.
This script traces the total elapsed time of different Tcl commands and
procedures and prints a report. Here it traces the example program,
Tracing... Hit Ctrl-C to end.
^C
Top 10 counts,
PID TYPE NAME COUNT
16028 cmd after 3
16028 cmd namespace 3
16028 cmd puts 3
16028 cmd lappend 4
16028 cmd lsearch 4
16028 cmd if 8
16028 cmd info 11
16028 cmd file 12
16028 cmd proc 12
0 total - 85
Top 10 exclusive elapsed times (us),
PID TYPE NAME TOTAL
16028 cmd tclInit 253
16028 cmd namespace 272
16028 proc func_c 330
16028 proc func_b 357
16028 proc func_a 363
16028 cmd file 416
16028 cmd if 852
16028 cmd source 929
16028 cmd after 3025152
0 total - 3030001
Top 10 inclusive elapsed times (us),
PID TYPE NAME TOTAL
16028 cmd uplevel 1849
16028 proc tclInit 2519
16028 cmd tclInit 2772
16028 proc func_c 1010031
16028 cmd func_c 1010088
16028 proc func_b 2020059
16028 cmd func_b 2020106
16028 cmd after 3025152
16028 proc func_a 3026545
16028 cmd func_a 3026572
The output is in three sections. The first shows the top ten most executed
commands while the script is tracing.
The second (Top 10 exclusive elapsed times) shows us the top ten slowest
commands or procedures, this number excludes any subroutines called during
command execution.
The third (Top 10 inclusive elapsed times) shows us the top ten slowest
commands or procedures including any time spent in subroutines. You can see
that func_a took the most amount of time all up. This makes sense if you
compare the code at Code/Tcl/func_abc.tcl with the results.