1The following are examples of pl_calldist.d. 2 3This script traces the elapsed time of Perl subroutines (functions) and 4prints a report containing distribution plots per subroutine. Here it 5traces the example program, Code/Perl/func_abc.pl. 6 7 # pl_calldist.d 8 Tracing... Hit Ctrl-C to end. 9 ^C 10 11 Exclusive subroutine elapsed times (us), 12 func_abc.pl, sub, func_a 13 value ------------- Distribution ------------- count 14 262144 | 0 15 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 16 1048576 | 0 17 18 func_abc.pl, sub, func_b 19 value ------------- Distribution ------------- count 20 262144 | 0 21 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 22 1048576 | 0 23 24 func_abc.pl, sub, func_c 25 value ------------- Distribution ------------- count 26 262144 | 0 27 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 28 1048576 | 0 29 30 31 Inclusive subroutine elapsed times (us), 32 func_abc.pl, sub, func_c 33 value ------------- Distribution ------------- count 34 262144 | 0 35 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 36 1048576 | 0 37 38 func_abc.pl, sub, func_b 39 value ------------- Distribution ------------- count 40 524288 | 0 41 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 42 2097152 | 0 43 44 func_abc.pl, sub, func_a 45 value ------------- Distribution ------------- count 46 1048576 | 0 47 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 48 4194304 | 0 49 50In total, 3 subroutines were called - func_a(), func_b(), and func_c(). 51 52The exclusive subroutine elapsed times show that each subroutine spent 53between 524 and 1048 ms. This exclusive time excludes the time spent in 54other subroutines. 55 56The inclusive subroutine elapsed times show that func_c() took between 0.5 and 571.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took 58between 2.1 and 4.2 seconds to execute. This inclusive time includes the 59time spent in other subroutines called, and since func_a() called func_b() 60which called func_c(), these times make sense. 61 62These elapsed times are the absolute time from when the subroutine began to 63when it completed - which includes off-CPU time due to other system events 64such as I/O, scheduling, interrupts, etc. 65 66Elapsed times are useful for identifying where latencies are. 67See Notes/ALLelapsed_notes.txt for more details. Also see 68Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 69detailed explanation of exclusive vs inclusive subroutine time. 70 71 72 73The following traces a Perl network interface statistics tool, "nicstat" 74version 0.99, 75 76# pl_calldist.d 77Tracing... Hit Ctrl-C to end. 78^C 79 80Exclusive subroutine elapsed times (us), 81 DynaLoader.pm, sub, dl_load_flags 82 value ------------- Distribution ------------- count 83 1 | 0 84 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 85 4 | 0 86 87 Config.pm, sub, TIEHASH 88 value ------------- Distribution ------------- count 89 2 | 0 90 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 91 8 | 0 92 93 Config.pm, sub, DESTROY 94 value ------------- Distribution ------------- count 95 4 | 0 96 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 97 16 | 0 98 99 Config.pm, sub, import 100 value ------------- Distribution ------------- count 101 4 | 0 102 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 103 16 | 0 104 105 register.pm, sub, mkMask 106 value ------------- Distribution ------------- count 107 2 | 0 108 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 109 8 | 0 110 111 Config.pm, sub, FETCH 112 value ------------- Distribution ------------- count 113 1 | 0 114 2 |@@@@@@@@@@@@@@@@@@@@ 2 115 4 |@@@@@@@@@@@@@@@@@@@@ 2 116 8 | 0 117 118 Config.pm, sub, BEGIN 119 value ------------- Distribution ------------- count 120 4 | 0 121 8 |@@@@@@@@@@@@@@@@@@@@ 1 122 16 |@@@@@@@@@@@@@@@@@@@@ 1 123 32 | 0 124 125 strict.pm, sub, import 126 value ------------- Distribution ------------- count 127 1 | 0 128 2 |@@@@@@@@ 1 129 4 |@@@@@@@@@@@@@@@@ 2 130 8 |@@@@@@@@ 1 131 16 |@@@@@@@@ 1 132 32 | 0 133 134 strict.pm, sub, bits 135 value ------------- Distribution ------------- count 136 2 | 0 137 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 138 8 |@@@@@@@ 1 139 16 |@@@@@@@ 1 140 32 | 0 141 142 strict.pm, sub, unimport 143 value ------------- Distribution ------------- count 144 4 | 0 145 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 146 16 |@@@@@@@@@@ 1 147 32 | 0 148 149 AutoLoader.pm, sub, BEGIN 150 value ------------- Distribution ------------- count 151 1 | 0 152 2 |@@@@@@@ 1 153 4 |@@@@@@@ 1 154 8 |@@@@@@@@@@@@@@@@@@@@ 3 155 16 |@@@@@@@ 1 156 32 | 0 157 158 Std.pm, sub, getopts 159 value ------------- Distribution ------------- count 160 32 | 0 161 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 162 128 | 0 163 164 register.pm, sub, import 165 value ------------- Distribution ------------- count 166 32 | 0 167 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 168 128 | 0 169 170 vars.pm, sub, import 171 value ------------- Distribution ------------- count 172 16 | 0 173 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 174 64 | 0 175 176 Exporter.pm, sub, import 177 value ------------- Distribution ------------- count 178 16 | 0 179 32 |@@@@@@@@@@@@@@@@@@@@ 1 180 64 |@@@@@@@@@@@@@@@@@@@@ 1 181 128 | 0 182 183 DynaLoader.pm, sub, bootstrap 184 value ------------- Distribution ------------- count 185 256 | 0 186 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 187 1024 | 0 188 189 warnings.pm, sub, BEGIN 190 value ------------- Distribution ------------- count 191 256 | 0 192 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 193 1024 | 0 194 195 DynaLoader.pm, sub, BEGIN 196 value ------------- Distribution ------------- count 197 128 | 0 198 256 |@@@@@@@@@@@@@@@@@@@@ 1 199 512 | 0 200 1024 |@@@@@@@@@@@@@@@@@@@@ 1 201 2048 | 0 202 203 nicstat, sub, print_neat 204 value ------------- Distribution ------------- count 205 32 | 0 206 64 |@@@@@@@@@@@@@@@@@@@@@@ 10 207 128 |@@@@@@@@@@@@@@@@@@ 8 208 256 | 0 209 210 vars.pm, sub, BEGIN 211 value ------------- Distribution ------------- count 212 1 | 0 213 2 |@@@@@@@@@@@@@ 1 214 4 | 0 215 8 |@@@@@@@@@@@@@ 1 216 16 | 0 217 32 | 0 218 64 | 0 219 128 | 0 220 256 | 0 221 512 | 0 222 1024 | 0 223 2048 |@@@@@@@@@@@@@ 1 224 4096 | 0 225 226 Kstat.pm, sub, BEGIN 227 value ------------- Distribution ------------- count 228 4 | 0 229 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 230 16 | 0 231 32 | 0 232 64 | 0 233 128 | 0 234 256 | 0 235 512 | 0 236 1024 | 0 237 2048 |@@@@@@@@@@@@@ 1 238 4096 | 0 239 240 nicstat, sub, BEGIN 241 value ------------- Distribution ------------- count 242 128 | 0 243 256 |@@@@@@@@@@@@@ 1 244 512 |@@@@@@@@@@@@@ 1 245 1024 | 0 246 2048 |@@@@@@@@@@@@@ 1 247 4096 | 0 248 249 nicstat, sub, fetch_net_data 250 value ------------- Distribution ------------- count 251 16384 | 0 252 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 253 65536 | 0 254 255 nicstat, sub, find_nets 256 value ------------- Distribution ------------- count 257 16384 | 0 258 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 259 65536 | 0 260 261 262Inclusive subroutine elapsed times (us), 263 DynaLoader.pm, sub, dl_load_flags 264 value ------------- Distribution ------------- count 265 1 | 0 266 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 267 4 | 0 268 269 Config.pm, sub, TIEHASH 270 value ------------- Distribution ------------- count 271 2 | 0 272 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 273 8 | 0 274 275 Config.pm, sub, DESTROY 276 value ------------- Distribution ------------- count 277 4 | 0 278 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 279 16 | 0 280 281 Config.pm, sub, import 282 value ------------- Distribution ------------- count 283 4 | 0 284 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 285 16 | 0 286 287 register.pm, sub, mkMask 288 value ------------- Distribution ------------- count 289 2 | 0 290 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 291 8 | 0 292 293 Config.pm, sub, FETCH 294 value ------------- Distribution ------------- count 295 1 | 0 296 2 |@@@@@@@@@@@@@@@@@@@@ 2 297 4 |@@@@@@@@@@@@@@@@@@@@ 2 298 8 | 0 299 300 strict.pm, sub, bits 301 value ------------- Distribution ------------- count 302 2 | 0 303 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 304 8 |@@@@@@@ 1 305 16 |@@@@@@@ 1 306 32 | 0 307 308 strict.pm, sub, import 309 value ------------- Distribution ------------- count 310 1 | 0 311 2 |@@@@@@@@ 1 312 4 |@@@@@@@@@@@@@@@@ 2 313 8 | 0 314 16 |@@@@@@@@@@@@@@@@ 2 315 32 | 0 316 317 Config.pm, sub, BEGIN 318 value ------------- Distribution ------------- count 319 8 | 0 320 16 |@@@@@@@@@@@@@@@@@@@@ 1 321 32 |@@@@@@@@@@@@@@@@@@@@ 1 322 64 | 0 323 324 Std.pm, sub, getopts 325 value ------------- Distribution ------------- count 326 32 | 0 327 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 328 128 | 0 329 330 register.pm, sub, import 331 value ------------- Distribution ------------- count 332 32 | 0 333 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 334 128 | 0 335 336 strict.pm, sub, unimport 337 value ------------- Distribution ------------- count 338 8 | 0 339 16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 340 32 | 0 341 342 vars.pm, sub, import 343 value ------------- Distribution ------------- count 344 16 | 0 345 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 346 64 | 0 347 348 AutoLoader.pm, sub, BEGIN 349 value ------------- Distribution ------------- count 350 1 | 0 351 2 |@@@@@@@ 1 352 4 |@@@@@@@ 1 353 8 | 0 354 16 |@@@@@@@@@@@@@@@@@@@@ 3 355 32 |@@@@@@@ 1 356 64 | 0 357 358 Exporter.pm, sub, import 359 value ------------- Distribution ------------- count 360 16 | 0 361 32 |@@@@@@@@@@@@@@@@@@@@ 1 362 64 |@@@@@@@@@@@@@@@@@@@@ 1 363 128 | 0 364 365 DynaLoader.pm, sub, bootstrap 366 value ------------- Distribution ------------- count 367 256 | 0 368 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 369 1024 | 0 370 371 warnings.pm, sub, BEGIN 372 value ------------- Distribution ------------- count 373 256 | 0 374 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 375 1024 | 0 376 377 nicstat, sub, print_neat 378 value ------------- Distribution ------------- count 379 32 | 0 380 64 |@@@@@@@@@@@@@@@@@@@@@@ 10 381 128 |@@@@@@@@@@@@@@@@@@ 8 382 256 | 0 383 384 vars.pm, sub, BEGIN 385 value ------------- Distribution ------------- count 386 1 | 0 387 2 |@@@@@@@@@@@@@ 1 388 4 | 0 389 8 | 0 390 16 | 0 391 32 |@@@@@@@@@@@@@ 1 392 64 | 0 393 128 | 0 394 256 | 0 395 512 | 0 396 1024 | 0 397 2048 |@@@@@@@@@@@@@ 1 398 4096 | 0 399 400 DynaLoader.pm, sub, BEGIN 401 value ------------- Distribution ------------- count 402 512 | 0 403 1024 |@@@@@@@@@@@@@@@@@@@@ 1 404 2048 |@@@@@@@@@@@@@@@@@@@@ 1 405 4096 | 0 406 407 Kstat.pm, sub, BEGIN 408 value ------------- Distribution ------------- count 409 8 | 0 410 16 |@@@@@@@@@@@@@ 1 411 32 |@@@@@@@@@@@@@ 1 412 64 | 0 413 128 | 0 414 256 | 0 415 512 | 0 416 1024 | 0 417 2048 | 0 418 4096 | 0 419 8192 |@@@@@@@@@@@@@ 1 420 16384 | 0 421 422 nicstat, sub, BEGIN 423 value ------------- Distribution ------------- count 424 256 | 0 425 512 |@@@@@@@@@@@@@ 1 426 1024 | 0 427 2048 |@@@@@@@@@@@@@ 1 428 4096 | 0 429 8192 |@@@@@@@@@@@@@ 1 430 16384 | 0 431 432 nicstat, sub, fetch_net_data 433 value ------------- Distribution ------------- count 434 16384 | 0 435 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 436 65536 | 0 437 438 nicstat, sub, find_nets 439 value ------------- Distribution ------------- count 440 16384 | 0 441 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 442 65536 | 0 443 444As an example of interpreting the output: the inclusive elapsed time for 445the "print_neat" subroutine in "nicstat", 446 447 nicstat, sub, print_neat 448 value ------------- Distribution ------------- count 449 32 | 0 450 64 |@@@@@@@@@@@@@@@@@@@@@@ 10 451 128 |@@@@@@@@@@@@@@@@@@ 8 452 256 | 0 453 454shows that "print_neat" was called 18 times, 10 of which took between 64 455and 127 microseconds, and 8 of which took between 128 and 255 microseconds. 456 457