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