cddl/contrib/dtracetoolkit/Examples/pridist_example.txt

   1 The following are demonstrations of the pridist.d script.
   2
   3
   4 Here we run pridist.d for a few seconds then hit Ctrl-C,
   5
   6    # pridist.d
   7    Sampling... Hit Ctrl-C to end.
   8    ^C
   9     CMD: setiathome       PID: 2190
  10
  11               value  ------------- Distribution ------------- count
  12                  -5 |                                         0
  13                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 6629
  14                   5 |                                         0
  15
  16     CMD: sshd             PID: 9172
  17
  18               value  ------------- Distribution ------------- count
  19                  50 |                                         0
  20                  55 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 10
  21                  60 |                                         0
  22
  23     CMD: mozilla-bin      PID: 3164
  24
  25               value  ------------- Distribution ------------- count
  26                  40 |                                         0
  27                  45 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 20
  28                  50 |                                         0
  29
  30     CMD: perl             PID: 11544
  31
  32               value  ------------- Distribution ------------- count
  33                  10 |                                         0
  34                  15 |@@@@@@@@                                 60
  35                  20 |                                         0
  36                  25 |@@@@@@@@@@@@@@@                          120
  37                  30 |                                         0
  38                  35 |@@@@@@@@@@                               80
  39                  40 |                                         0
  40                  45 |@@@@@                                    40
  41                  50 |                                         0
  42                  55 |@@@                                      20
  43                  60 |                                         0
  44
  45 During this sample there was a CPU bound process called "setiathome"
  46 running, and a new CPU bound "perl" process was executed.
  47
  48 perl, executing an infinite loop, begins with a high priority of 55 to 59
  49 where it is sampled 20 times. pridist.d samples 1000 times per second,
  50 so this equates to 20 ms. The perl process has also been sampled for 40 ms
  51 at priority 45 to 49, for 80 ms at priority 35 to 39, down to 60 ms at a
  52 priority 15 to 19 - at which point I had hit Ctrl-C to end sampling.
  53
  54 The output is spectacular as it matches the behaviour of the dispatcher
  55 table for the time sharing class perfectly!
  56
  57 setiathome is running with the lowest priority, in the 0 to 4 range.
  58
  59 ... ok, so when I say 20 samples equates 20 ms, we know that's only an
  60 estimate. It really means that for 20 samples that process was the one on
  61 the CPU. In between the samples anything may have occured (I/O bound
  62 processes will context switch off the CPU). DTrace can certainly be used
  63 to measure this based on schedular events not samples (eg, cpudist),
  64 however DTrace can then sometimes consume a noticable portion of the CPUs
  65 (for example, 2%).
  66
  67
  68
  69
  70 The following is a longer sample. Again, I start a new CPU bound perl
  71 process,
  72
  73    # pridist.d
  74    Sampling... Hit Ctrl-C to end.
  75    ^C
  76     CMD: setiathome       PID: 2190
  77
  78               value  ------------- Distribution ------------- count
  79                  -5 |                                         0
  80                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1820
  81                   5 |                                         0
  82
  83     CMD: mozilla-bin      PID: 3164
  84
  85               value  ------------- Distribution ------------- count
  86                  40 |                                         0
  87                  45 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 10
  88                  50 |                                         0
  89
  90     CMD: bash             PID: 9185
  91
  92               value  ------------- Distribution ------------- count
  93                  50 |                                         0
  94                  55 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 10
  95                  60 |                                         0
  96
  97     CMD: perl             PID: 11547
  98
  99               value  ------------- Distribution ------------- count
 100                  -5 |                                         0
 101                   0 |@@@@@@@@@@@@@@@                          2020
 102                   5 |@@                                       200
 103                  10 |@@@@@@@                                  960
 104                  15 |@                                        160
 105                  20 |@@@@@                                    720
 106                  25 |@                                        120
 107                  30 |@@@@                                     480
 108                  35 |@                                        80
 109                  40 |@@                                       240
 110                  45 |                                         40
 111                  50 |@@                                       240
 112                  55 |                                         10
 113                  60 |                                         0
 114
 115 Now other behaviour can be observed as the perl process runs. The effect
 116 here is due to ts_maxwait triggering a priority boot to avoid CPU starvation;
 117 the priority is boosted to the 50 to 54 range, then decreases by 10 until
 118 it reaches 0 and another ts_maxwait is triggered. The process spends
 119 more time at lower priorities, as that is exactly how the TS dispatch table
 120 has been configured.
 121
 122
 123
 124
 125 Now we run prdist.d for a considerable time,
 126
 127    # pridist.d
 128    Sampling... Hit Ctrl-C to end.
 129    ^C
 130     CMD: setiathome       PID: 2190
 131
 132               value  ------------- Distribution ------------- count
 133                  -5 |                                         0
 134                   0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3060
 135                   5 |                                         0
 136
 137     CMD: mozilla-bin      PID: 3164
 138
 139               value  ------------- Distribution ------------- count
 140                  40 |                                         0
 141                  45 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 20
 142                  50 |                                         0
 143
 144     CMD: perl             PID: 11549
 145
 146               value  ------------- Distribution ------------- count
 147                  -5 |                                         0
 148                   0 |@@@@@@@@@@@@@@@@@@@                      7680
 149                   5 |                                         0
 150                  10 |@@@@@@@                                  3040
 151                  15 |                                         70
 152                  20 |@@@@@@                                   2280
 153                  25 |                                         120
 154                  30 |@@@@                                     1580
 155                  35 |                                         80
 156                  40 |@@                                       800
 157                  45 |                                         40
 158                  50 |@@                                       800
 159                  55 |                                         20
 160                  60 |                                         0
 161
 162 The process has settled to a pattern of 0 priority, ts_maxwait boot to 50,
 163 drop back to 0.
 164
 165 Run "dispadmin -c TS -g" for a printout of the time sharing dispatcher table.
 166
 167
 168
 169
 170
 171 The following shows running pridist.d on a completely idle system,
 172
 173    # pridist.d
 174    Sampling... Hit Ctrl-C to end.
 175    ^C
 176     CMD: sched            PID: 0
 177
 178               value  ------------- Distribution ------------- count
 179                 -10 |                                         0
 180                  -5 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1190
 181                   0 |                                         0
 182
 183 Only the kernel "sched" was sampled. It would have been running the idle
 184 thread.
 185
 186
 187
 188
 189 The following is an unusual output that is worth mentioning,
 190
 191    # pridist.d
 192    Sampling... Hit Ctrl-C to end.
 193    ^C
 194     CMD: sched            PID: 0
 195
 196               value  ------------- Distribution ------------- count
 197                 -10 |                                         0
 198                  -5 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 940
 199                   0 |                                         0
 200                   5 |                                         0
 201                  10 |                                         0
 202                  15 |                                         0
 203                  20 |                                         0
 204                  25 |                                         0
 205                  30 |                                         0
 206                  35 |                                         0
 207                  40 |                                         0
 208                  45 |                                         0
 209                  50 |                                         0
 210                  55 |                                         0
 211                  60 |                                         0
 212                  65 |                                         0
 213                  70 |                                         0
 214                  75 |                                         0
 215                  80 |                                         0
 216                  85 |                                         0
 217                  90 |                                         0
 218                  95 |                                         0
 219                 100 |                                         0
 220                 105 |                                         0
 221                 110 |                                         0
 222                 115 |                                         0
 223                 120 |                                         0
 224                 125 |                                         0
 225                 130 |                                         0
 226                 135 |                                         0
 227                 140 |                                         0
 228                 145 |                                         0
 229                 150 |                                         0
 230                 155 |                                         0
 231                 160 |                                         0
 232                 165 |                                         10
 233              >= 170 |                                         0
 234
 235 Here we have sampled the kernel running at a priority of 165 to 169. This
 236 is the interrupt priority range, and would be an interrupt servicing thread.
 237 Eg, a network interrupt.
 238