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, Code/Tcl/func_abc.tcl # tcl_calltime.d 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. |