cddl/contrib/dtracetoolkit/Examples/tcl_calltime_example.txt

   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