cddl/contrib/dtracetoolkit/Examples/pl_cpudist_example.txt

   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