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