cddl/contrib/dtracetoolkit/Examples/pl_calldist_example.txt

   1 The following are examples of pl_calldist.d.
   2
   3 This script traces the elapsed 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_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
  50 In total, 3 subroutines were called - func_a(), func_b(), and func_c().
  51
  52 The exclusive subroutine elapsed times show that each subroutine spent
  53 between 524 and 1048 ms. This exclusive time excludes the time spent in
  54 other subroutines.
  55
  56 The inclusive subroutine elapsed times show that func_c() took between 0.5 and
  57 1.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took
  58 between 2.1 and 4.2 seconds to execute. This inclusive time includes the
  59 time spent in other subroutines called, and since func_a() called func_b()
  60 which called func_c(), these times make sense.
  61
  62 These elapsed times are the absolute time from when the subroutine began to
  63 when it completed - which includes off-CPU time due to other system events
  64 such as I/O, scheduling, interrupts, etc.
  65
  66 Elapsed times are useful for identifying where latencies are.
  67 See Notes/ALLelapsed_notes.txt for more details. Also see
  68 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  69 detailed explanation of exclusive vs inclusive subroutine time.
  70
  71
  72
  73 The following traces a Perl network interface statistics tool, "nicstat"
  74 version 0.99,
  75
  76 # pl_calldist.d
  77 Tracing... Hit Ctrl-C to end.
  78 ^C
  79
  80 Exclusive 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
 262 Inclusive 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
 444 As an example of interpreting the output: the inclusive elapsed time for
 445 the "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
 454 shows that "print_neat" was called 18 times, 10 of which took between 64
 455 and 127 microseconds, and 8 of which took between 128 and 255 microseconds.
 456