1The following are demonstrations of the pridist.d script. 2 3 4Here 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 45During this sample there was a CPU bound process called "setiathome" 46running, and a new CPU bound "perl" process was executed. 47 48perl, executing an infinite loop, begins with a high priority of 55 to 59 49where it is sampled 20 times. pridist.d samples 1000 times per second, 50so this equates to 20 ms. The perl process has also been sampled for 40 ms 51at priority 45 to 49, for 80 ms at priority 35 to 39, down to 60 ms at a 52priority 15 to 19 - at which point I had hit Ctrl-C to end sampling. 53 54The output is spectacular as it matches the behaviour of the dispatcher 55table for the time sharing class perfectly! 56 57setiathome 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 60estimate. It really means that for 20 samples that process was the one on 61the CPU. In between the samples anything may have occured (I/O bound 62processes will context switch off the CPU). DTrace can certainly be used 63to measure this based on schedular events not samples (eg, cpudist), 64however DTrace can then sometimes consume a noticable portion of the CPUs 65(for example, 2%). 66 67 68 69 70The following is a longer sample. Again, I start a new CPU bound perl 71process, 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 115Now other behaviour can be observed as the perl process runs. The effect 116here is due to ts_maxwait triggering a priority boot to avoid CPU starvation; 117the priority is boosted to the 50 to 54 range, then decreases by 10 until 118it reaches 0 and another ts_maxwait is triggered. The process spends 119more time at lower priorities, as that is exactly how the TS dispatch table 120has been configured. 121 122 123 124 125Now 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 162The process has settled to a pattern of 0 priority, ts_maxwait boot to 50, 163drop back to 0. 164 165Run "dispadmin -c TS -g" for a printout of the time sharing dispatcher table. 166 167 168 169 170 171The 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 183Only the kernel "sched" was sampled. It would have been running the idle 184thread. 185 186 187 188 189The 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 235Here we have sampled the kernel running at a priority of 165 to 169. This 236is the interrupt priority range, and would be an interrupt servicing thread. 237Eg, a network interrupt. 238 239