Home | History | Annotate | Line # | Download | only in Examples
      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