Home | History | Annotate | Line # | Download | only in Examples
      1 The following are examples of tcl_calldist.d.
      2 
      3 This script traces the elapsed time of Tcl procedures and commands and
      4 prints a report containing distribution plots per function. Here it traces the
      5 example program, Code/Tcl/func_abc.tcl
      6 
      7 # tcl_calldist.d
      8 Tracing... Hit Ctrl-C to end.
      9 ^C
     10 
     11 Top 10 exclusive elapsed times (us),
     12    PID=16033, cmd, namespace 
     13            value  ------------- Distribution ------------- count    
     14                1 |                                         0        
     15                2 |@@@@@@@@@@@@@                            1        
     16                4 |@@@@@@@@@@@@@                            1        
     17                8 |                                         0        
     18               16 |                                         0        
     19               32 |                                         0        
     20               64 |                                         0        
     21              128 |@@@@@@@@@@@@@                            1        
     22              256 |                                         0        
     23 
     24    PID=16033, cmd, puts 
     25            value  ------------- Distribution ------------- count    
     26               16 |                                         0        
     27               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2        
     28               64 |                                         0        
     29              128 |@@@@@@@@@@@@@                            1        
     30              256 |                                         0        
     31 
     32    PID=16033, cmd, tclInit 
     33            value  ------------- Distribution ------------- count    
     34              128 |                                         0        
     35              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
     36              512 |                                         0        
     37 
     38    PID=16033, proc, func_a 
     39            value  ------------- Distribution ------------- count    
     40              128 |                                         0        
     41              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
     42              512 |                                         0        
     43 
     44    PID=16033, proc, func_b 
     45            value  ------------- Distribution ------------- count    
     46              128 |                                         0        
     47              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
     48              512 |                                         0        
     49 
     50    PID=16033, proc, func_c 
     51            value  ------------- Distribution ------------- count    
     52              128 |                                         0        
     53              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
     54              512 |                                         0        
     55 
     56    PID=16033, cmd, file 
     57            value  ------------- Distribution ------------- count    
     58                2 |                                         0        
     59                4 |@@@@@@@@@@@@@                            4        
     60                8 |@@@@@@@                                  2        
     61               16 |@@@@@@@                                  2        
     62               32 |@@@                                      1        
     63               64 |@@@@@@@@@@                               3        
     64              128 |                                         0        
     65 
     66    PID=16033, cmd, source 
     67            value  ------------- Distribution ------------- count    
     68              256 |                                         0        
     69              512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
     70             1024 |                                         0        
     71 
     72    PID=16033, cmd, if 
     73            value  ------------- Distribution ------------- count    
     74                8 |                                         0        
     75               16 |@@@@@@@@@@@@@@@@@@@@                     4        
     76               32 |@@@@@@@@@@@@@@@                          3        
     77               64 |                                         0        
     78              128 |                                         0        
     79              256 |                                         0        
     80              512 |@@@@@                                    1        
     81             1024 |                                         0        
     82 
     83    PID=16033, cmd, after 
     84            value  ------------- Distribution ------------- count    
     85           262144 |                                         0        
     86           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
     87          1048576 |                                         0        
     88 
     89 
     90 Top 10 inclusive elapsed times (us),
     91    PID=16033, cmd, uplevel 
     92            value  ------------- Distribution ------------- count    
     93              512 |                                         0        
     94             1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
     95             2048 |                                         0        
     96 
     97    PID=16033, cmd, tclInit 
     98            value  ------------- Distribution ------------- count    
     99             1024 |                                         0        
    100             2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    101             4096 |                                         0        
    102 
    103    PID=16033, proc, tclInit 
    104            value  ------------- Distribution ------------- count    
    105             1024 |                                         0        
    106             2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    107             4096 |                                         0        
    108 
    109    PID=16033, cmd, func_c 
    110            value  ------------- Distribution ------------- count    
    111           262144 |                                         0        
    112           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    113          1048576 |                                         0        
    114 
    115    PID=16033, proc, func_c 
    116            value  ------------- Distribution ------------- count    
    117           262144 |                                         0        
    118           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    119          1048576 |                                         0        
    120 
    121    PID=16033, cmd, func_b 
    122            value  ------------- Distribution ------------- count    
    123           524288 |                                         0        
    124          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    125          2097152 |                                         0        
    126 
    127    PID=16033, proc, func_b 
    128            value  ------------- Distribution ------------- count    
    129           524288 |                                         0        
    130          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    131          2097152 |                                         0        
    132 
    133    PID=16033, cmd, after 
    134            value  ------------- Distribution ------------- count    
    135           262144 |                                         0        
    136           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3        
    137          1048576 |                                         0        
    138 
    139    PID=16033, cmd, func_a 
    140            value  ------------- Distribution ------------- count    
    141          1048576 |                                         0        
    142          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    143          4194304 |                                         0        
    144 
    145    PID=16033, proc, func_a 
    146            value  ------------- Distribution ------------- count    
    147          1048576 |                                         0        
    148          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
    149          4194304 |                                         0        
    150 
    151 The exclusive function elapsed times show that each func_a took between 256
    152 and 511 microseconds. This time excludes the time spent in any other functions.
    153 
    154 The inclusive elapsed times section shows that each func_a spent
    155 took between 2.1 and 4.2 seconds. This time also includes the time spent in
    156 any other commands or procedures called by func_a.
    157 
    158 These elapsed times are the absolute time from when the function began to
    159 when it completed - which includes off-CPU time due to other system events
    160 such as I/O, scheduling, interrupts, etc.
    161 
    162 Elapsed times are useful for identifying where latencies are.
    163 See Notes/ALLelapsed_notes.txt for more details. Also see
    164 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
    165 detailed explanation of exclusive vs inclusive function time.
    166 
    167