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