tcl_calltime_example.txt revision 1.1 1 The following are examples of tcl_calltime.d.
2
3 This script traces the total elapsed time of different Tcl commands and
4 procedures and prints a report. Here it traces the example program,
5 Code/Tcl/func_abc.tcl
6
7 # tcl_calltime.d
8 Tracing... Hit Ctrl-C to end.
9 ^C
10
11 Top 10 counts,
12 PID TYPE NAME COUNT
13 16028 cmd after 3
14 16028 cmd namespace 3
15 16028 cmd puts 3
16 16028 cmd lappend 4
17 16028 cmd lsearch 4
18 16028 cmd if 8
19 16028 cmd info 11
20 16028 cmd file 12
21 16028 cmd proc 12
22 0 total - 85
23
24 Top 10 exclusive elapsed times (us),
25 PID TYPE NAME TOTAL
26 16028 cmd tclInit 253
27 16028 cmd namespace 272
28 16028 proc func_c 330
29 16028 proc func_b 357
30 16028 proc func_a 363
31 16028 cmd file 416
32 16028 cmd if 852
33 16028 cmd source 929
34 16028 cmd after 3025152
35 0 total - 3030001
36
37 Top 10 inclusive elapsed times (us),
38 PID TYPE NAME TOTAL
39 16028 cmd uplevel 1849
40 16028 proc tclInit 2519
41 16028 cmd tclInit 2772
42 16028 proc func_c 1010031
43 16028 cmd func_c 1010088
44 16028 proc func_b 2020059
45 16028 cmd func_b 2020106
46 16028 cmd after 3025152
47 16028 proc func_a 3026545
48 16028 cmd func_a 3026572
49
50 The output is in three sections. The first shows the top ten most executed
51 commands while the script is tracing.
52
53 The second (Top 10 exclusive elapsed times) shows us the top ten slowest
54 commands or procedures, this number excludes any subroutines called during
55 command execution.
56
57 The third (Top 10 inclusive elapsed times) shows us the top ten slowest
58 commands or procedures including any time spent in subroutines. You can see
59 that func_a took the most amount of time all up. This makes sense if you
60 compare the code at Code/Tcl/func_abc.tcl with the results.
61
62