239 lines
10 KiB
Plaintext
239 lines
10 KiB
Plaintext
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.
|
|
|