cddl/contrib/dtracetoolkit/Examples/tcl_calltime_example.txt


1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61

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.