1The following are examples of sh_calldist.d. 2 3This script traces the elapsed time of Bourne shell functions and 4prints a report containing distribution plots per function. Here it 5traces the example program, Code/Shell/func_abc.sh. 6 7 # sh_calldist.d 8 Tracing... Hit Ctrl-C to end. 9 ^C 10 11 Elapsed times (us), 12 13 func_abc.sh, builtin, echo 14 value ------------- Distribution ------------- count 15 8 | 0 16 16 |@@@@@@@@@@@@@ 1 17 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 18 64 | 0 19 20 func_abc.sh, cmd, sleep 21 value ------------- Distribution ------------- count 22 262144 | 0 23 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 24 1048576 | 0 25 26 Exclusive function elapsed times (us), 27 28 func_abc.sh, func, func_a 29 value ------------- Distribution ------------- count 30 1024 | 0 31 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 32 4096 | 0 33 34 func_abc.sh, func, func_b 35 value ------------- Distribution ------------- count 36 1024 | 0 37 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 38 4096 | 0 39 40 func_abc.sh, func, func_c 41 value ------------- Distribution ------------- count 42 1024 | 0 43 2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 44 4096 | 0 45 46 Inclusive function elapsed times (us), 47 48 func_abc.sh, func, func_c 49 value ------------- Distribution ------------- count 50 262144 | 0 51 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 52 1048576 | 0 53 54 func_abc.sh, func, func_b 55 value ------------- Distribution ------------- count 56 524288 | 0 57 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 58 2097152 | 0 59 60 func_abc.sh, func, func_a 61 value ------------- Distribution ------------- count 62 1048576 | 0 63 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 64 4194304 | 0 65 66The elapsed times show that the echo builtin takes between 16 and 64 us 67to execute. 68 69The exclusive function elapsed times show that each function spent 70between 2 and 4 ms. This exclusive time excludes the time spent in 71other functions. 72 73The inclusive function elapsed times show that func_c() took between 0.5 and 741.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took 75between 2.1 and 4.2 seconds to execute. This inclusive time includes the 76time spent in other functions and commands called, and since func_a() 77calls func_b() which calls func_c(), and, each function is calling "sleep 1", 78these times make sense. 79 80These elapsed times are the absolute time from when the function began to 81when it completed - which includes off-CPU time due to other system events 82such as I/O, scheduling, interrupts, etc. 83 84Elapsed times are useful for identifying where latencies are. 85See Notes/ALLelapsed_notes.txt for more details. Also see 86Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 87detailed explanation of exclusive vs inclusive function time. 88 89 90 91The following traces the firefox startup script. 92 93# sh_calldist.d 94Tracing... Hit Ctrl-C to end. 95^C 96 97Elapsed times (us), 98 99 run-mozilla.sh, builtin, return 100 value ------------- Distribution ------------- count 101 0 | 0 102 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 103 2 | 0 104 105 run-mozilla.sh, builtin, shift 106 value ------------- Distribution ------------- count 107 0 | 0 108 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 109 2 | 0 110 111 run-mozilla.sh, builtin, break 112 value ------------- Distribution ------------- count 113 1 | 0 114 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 115 4 | 0 116 117 firefox, builtin, break 118 value ------------- Distribution ------------- count 119 2 | 0 120 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 121 8 | 0 122 123 run-mozilla.sh, builtin, export 124 value ------------- Distribution ------------- count 125 0 | 0 126 1 |@@@@@@@@@@@@@ 1 127 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 128 4 | 0 129 130 firefox, builtin, export 131 value ------------- Distribution ------------- count 132 1 | 0 133 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 134 4 |@@@@@@@@@@@@@ 1 135 8 | 0 136 137 firefox, builtin, : 138 value ------------- Distribution ------------- count 139 0 | 0 140 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 5 141 2 | 0 142 4 |@@@@@@@ 1 143 8 | 0 144 145 firefox, builtin, pwd 146 value ------------- Distribution ------------- count 147 16 | 0 148 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 149 64 | 0 150 151 firefox, builtin, test 152 value ------------- Distribution ------------- count 153 16 | 0 154 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 155 64 | 0 156 157 firefox, builtin, cd 158 value ------------- Distribution ------------- count 159 4 | 0 160 8 |@@@@@@@@@@@@@ 1 161 16 |@@@@@@@@@@@@@ 1 162 32 |@@@@@@@@@@@@@ 1 163 64 | 0 164 165 firefox, builtin, [ 166 value ------------- Distribution ------------- count 167 0 | 0 168 1 |@@@@@@@ 3 169 2 |@@ 1 170 4 |@@ 1 171 8 |@@@@@@@ 3 172 16 |@@@@@@@@@@@ 5 173 32 |@@@@@@@ 3 174 64 |@@@@ 2 175 128 | 0 176 177 run-mozilla.sh, builtin, type 178 value ------------- Distribution ------------- count 179 256 | 0 180 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 181 1024 | 0 182 183 run-mozilla.sh, builtin, [ 184 value ------------- Distribution ------------- count 185 0 | 0 186 1 |@@@@@@@@ 4 187 2 |@@@@@@@@@@ 5 188 4 |@@@@ 2 189 8 |@@@@@@ 3 190 16 |@@@@@@@@@@ 5 191 32 | 0 192 64 | 0 193 128 | 0 194 256 | 0 195 512 | 0 196 1024 | 0 197 2048 |@@ 1 198 4096 | 0 199 200 firefox, builtin, echo 201 value ------------- Distribution ------------- count 202 64 | 0 203 128 |@@@@@@@@@@@@@@@@@@@@ 1 204 256 | 0 205 512 | 0 206 1024 | 0 207 2048 |@@@@@@@@@@@@@@@@@@@@ 1 208 4096 | 0 209 210 firefox, cmd, /usr/lib/firefox/run-mozilla.sh 211 value ------------- Distribution ------------- count 212 2097152 | 0 213 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 214 8388608 | 0 215 216 run-mozilla.sh, cmd, /usr/lib/firefox/firefox-bin 217 value ------------- Distribution ------------- count 218 2097152 | 0 219 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 220 8388608 | 0 221 222Exclusive function elapsed times (us), 223 224 run-mozilla.sh, func, moz_test_binary 225 value ------------- Distribution ------------- count 226 16 | 0 227 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 228 64 | 0 229 230 firefox, func, moz_spc_verbose_echo 231 value ------------- Distribution ------------- count 232 2 | 0 233 4 |@@@@@@@@@@@@@ 2 234 8 |@@@@@@@@@@@@@ 2 235 16 |@@@@@@@@@@@@@ 2 236 32 | 0 237 238 firefox, func, moz_pis_startstop_scripts 239 value ------------- Distribution ------------- count 240 128 | 0 241 256 |@@@@@@@@@@@@@@@@@@@@ 1 242 512 | 0 243 1024 | 0 244 2048 | 0 245 4096 | 0 246 8192 | 0 247 16384 | 0 248 32768 |@@@@@@@@@@@@@@@@@@@@ 1 249 65536 | 0 250 251 run-mozilla.sh, func, moz_run_program 252 value ------------- Distribution ------------- count 253 65536 | 0 254 131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 255 262144 | 0 256 257Inclusive function elapsed times (us), 258 259 firefox, func, moz_spc_verbose_echo 260 value ------------- Distribution ------------- count 261 4 | 0 262 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 263 16 |@@@@@@@@@@@@@ 2 264 32 | 0 265 266 run-mozilla.sh, func, moz_test_binary 267 value ------------- Distribution ------------- count 268 32 | 0 269 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 270 128 | 0 271 272 firefox, func, moz_pis_startstop_scripts 273 value ------------- Distribution ------------- count 274 128 | 0 275 256 |@@@@@@@@@@@@@@@@@@@@ 1 276 512 | 0 277 1024 | 0 278 2048 | 0 279 4096 | 0 280 8192 | 0 281 16384 | 0 282 32768 |@@@@@@@@@@@@@@@@@@@@ 1 283 65536 | 0 284 285 run-mozilla.sh, func, moz_run_program 286 value ------------- Distribution ------------- count 287 2097152 | 0 288 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 289 8388608 | 0 290 291 292As an example of interpreting the output: the inclusive elapsed time for 293the "[" (test) builtin, 294 295 firefox, builtin, [ 296 value ------------- Distribution ------------- count 297 0 | 0 298 1 |@@@@@@@ 3 299 2 |@@ 1 300 4 |@@ 1 301 8 |@@@@@@@ 3 302 16 |@@@@@@@@@@@ 5 303 32 |@@@@@@@ 3 304 64 |@@@@ 2 305 128 | 0 306 307shows that it was called 17 times (after adding up the counts), 5 of which 308took between 16 and 31 microseconds. 309 310