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