diff options
Diffstat (limited to 'cddl/contrib/dtracetoolkit/Examples/pridist_example.txt')
| -rw-r--r-- | cddl/contrib/dtracetoolkit/Examples/pridist_example.txt | 238 |
1 files changed, 238 insertions, 0 deletions
diff --git a/cddl/contrib/dtracetoolkit/Examples/pridist_example.txt b/cddl/contrib/dtracetoolkit/Examples/pridist_example.txt new file mode 100644 index 000000000000..1f930ab03ce5 --- /dev/null +++ b/cddl/contrib/dtracetoolkit/Examples/pridist_example.txt @@ -0,0 +1,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. + |