1The following are examples of tcl_calldist.d. 2 3This script traces the elapsed time of Tcl procedures and commands and 4prints a report containing distribution plots per function. Here it traces the 5example program, Code/Tcl/func_abc.tcl 6 7# tcl_calldist.d 8Tracing... Hit Ctrl-C to end. 9^C 10 11Top 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 90Top 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 151The exclusive function elapsed times show that each func_a took between 256 152and 511 microseconds. This time excludes the time spent in any other functions. 153 154The inclusive elapsed times section shows that each func_a spent 155took between 2.1 and 4.2 seconds. This time also includes the time spent in 156any other commands or procedures called by func_a. 157 158These elapsed times are the absolute time from when the function began to 159when it completed - which includes off-CPU time due to other system events 160such as I/O, scheduling, interrupts, etc. 161 162Elapsed times are useful for identifying where latencies are. 163See Notes/ALLelapsed_notes.txt for more details. Also see 164Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 165detailed explanation of exclusive vs inclusive function time. 166 167