One common question you might want answered is which CPUs are running threads and for how long. You can use the on-cpu and off-cpu probes to easily answer this question on a system-wide basis as shown in the following example:
sched:::on-cpu { self->ts = timestamp; } sched:::off-cpu /self->ts/ { @[cpu] = quantize(timestamp - self->ts); self->ts = 0; }
Running the above script results in output similar to the following example:
# dtrace -s ./where.d dtrace: script './where.d' matched 5 probes ^C 0 value ------------- Distribution ------------- count 2048 | 0 4096 |@@ 37 8192 |@@@@@@@@@@@@@ 212 16384 |@ 30 32768 | 10 65536 |@ 17 131072 | 12 262144 | 9 524288 | 6 1048576 | 5 2097152 | 1 4194304 | 3 8388608 |@@@@ 75 16777216 |@@@@@@@@@@@@ 201 33554432 | 6 67108864 | 0 1 value ------------- Distribution ------------- count 2048 | 0 4096 |@ 6 8192 |@@@@ 23 16384 |@@@ 18 32768 |@@@@ 22 65536 |@@@@ 22 131072 |@ 7 262144 | 5 524288 | 2 1048576 | 3 2097152 |@ 9 4194304 | 4 8388608 |@@@ 18 16777216 |@@@ 19 33554432 |@@@ 16 67108864 |@@@@ 21 134217728 |@@ 14 268435456 | 0 |
The above output shows that on CPU 1 threads tend to run for less than 100 microseconds at a stretch, or for approximately 10 milliseconds. A noticeable gap between the two clusters of data shown in the histogram. You also might be interested in knowing which CPUs are running a particular process. You can use the on-cpu and off-cpu probes for answering this question as well. The following script displays which CPUs run a specified application over a period of ten seconds:
#pragma D option quiet dtrace:::BEGIN { start = timestamp; } sched:::on-cpu /execname == $$1/ { self->ts = timestamp; } sched:::off-cpu /self->ts/ { @[cpu] = sum(timestamp - self->ts); self->ts = 0; } profile:::tick-1sec /++x == 10/ { exit(0); } dtrace:::END { printf("CPU distribution of imapd over %d seconds:\n\n", (timestamp - start) / 1000000000); printf("CPU microseconds\n--- ------------\n"); normalize(@, 1000); printa("%3d %@d\n", @); }
Running the above script on a large mail server and specifying the IMAP daemon results in output similar to the following example:
# dtrace -s ./whererun.d imapd CPU distribution of imapd over 10 seconds: CPU microseconds --- ------------ 15 10102 12 16377 21 25317 19 25504 17 35653 13 41539 14 46669 20 57753 22 70088 16 115860 23 127775 18 160517 |
Solaris takes into account the amount of time that a thread has been sleeping when selecting a CPU on which to run the thread: a thread that has been sleeping for less time tends not to migrate. You can use the off-cpu and on-cpu probes to observe this behavior:
sched:::off-cpu /curlwpsinfo->pr_state == SSLEEP/ { self->cpu = cpu; self->ts = timestamp; } sched:::on-cpu /self->ts/ { @[self->cpu == cpu ? "sleep time, no CPU migration" : "sleep time, CPU migration"] = lquantize((timestamp - self->ts) / 1000000, 0, 500, 25); self->ts = 0; self->cpu = 0; }
Running the above script for approximately 30 seconds results in output similar to the following example:
# dtrace -s ./howlong.d dtrace: script './howlong.d' matched 5 probes ^C sleep time, CPU migration value -------------- Distribution ------------ count < 0 | 0 0 |@@@@@@@ 6838 25 |@@@@@ 4714 50 |@@@ 3108 75 |@ 1304 100 |@ 1557 125 |@ 1425 150 | 894 175 |@ 1526 200 |@@ 2010 225 |@@ 1933 250 |@@ 1982 275 |@@ 2051 300 |@@ 2021 325 |@ 1708 350 |@ 1113 375 | 502 400 | 220 425 | 106 450 | 54 475 | 40 >= 500 |@ 1716 sleep time, no CPU migration value -------------- Distribution ------------ count < 0 | 0 0 |@@@@@@@@@@@@ 58413 25 |@@@ 14793 50 |@@ 10050 75 | 3858 100 |@ 6242 125 |@ 6555 150 | 3980 175 |@ 5987 200 |@ 9024 225 |@ 9070 250 |@@ 10745 275 |@@ 11898 300 |@@ 11704 325 |@@ 10846 350 |@ 6962 375 | 3292 400 | 1713 425 | 585 450 | 201 475 | 96 >= 500 | 3946 |
The example output shows that there are many more occurences of non-migration than migration. Also, when sleep times are longer, migrations are more likely. The distributions are noticeably different in the sub-100 millisecond range, but look very similar as the sleep times get longer. This result would seem to indicate that sleep time is not factored into the scheduling decision once a certain threshold is exceeded.
The final example using off-cpu and on-cpu shows how to use these probes along with the pr_stype field to determine why threads sleep and for how long:
sched:::off-cpu /curlwpsinfo->pr_state == SSLEEP/ { /* * We're sleeping. Track our sobj type. */ self->sobj = curlwpsinfo->pr_stype; self->bedtime = timestamp; } sched:::off-cpu /curlwpsinfo->pr_state == SRUN/ { self->bedtime = timestamp; } sched:::on-cpu /self->bedtime && !self->sobj/ { @["preempted"] = quantize(timestamp - self->bedtime); self->bedtime = 0; } sched:::on-cpu /self->sobj/ { @[self->sobj == SOBJ_MUTEX ? "kernel-level lock" : self->sobj == SOBJ_RWLOCK ? "rwlock" : self->sobj == SOBJ_CV ? "condition variable" : self->sobj == SOBJ_SEMA ? "semaphore" : self->sobj == SOBJ_USER ? "user-level lock" : self->sobj == SOBJ_USER_PI ? "user-level prio-inheriting lock" : self->sobj == SOBJ_SHUTTLE ? "shuttle" : "unknown"] = quantize(timestamp - self->bedtime); self->sobj = 0; self->bedtime = 0; }
Running the above script for several seconds results in output similar to the following example:
# dtrace -s ./whatfor.d dtrace: script './whatfor.d' matched 12 probes ^C kernel-level lock value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@@@@ 3 65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 11 131072 |@@ 1 262144 | 0 preempted value -------------- Distribution ------------ count 16384 | 0 32768 | 4 65536 |@@@@@@@@ 408 131072 |@@@@@@@@@@@@@@@@@@@@@@ 1031 262144 |@@@ 156 524288 |@@ 116 1048576 |@ 51 2097152 | 42 4194304 | 16 8388608 | 15 16777216 | 4 33554432 | 8 67108864 | 0 semaphore value -------------- Distribution ------------ count 32768 | 0 65536 |@@ 61 131072 |@@@@@@@@@@@@@@@@@@@@@@@@ 553 262144 |@@ 63 524288 |@ 36 1048576 | 7 2097152 | 22 4194304 |@ 44 8388608 |@@@ 84 16777216 |@ 36 33554432 | 3 67108864 | 6 134217728 | 0 268435456 | 0 536870912 | 0 1073741824 | 0 2147483648 | 0 4294967296 | 0 8589934592 | 0 17179869184 | 1 34359738368 | 0 shuttle value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@ 2 131072 |@@@@@@@@@@@@@@@@ 6 262144 |@@@@@ 2 524288 | 0 1048576 | 0 2097152 | 0 4194304 |@@@@@ 2 8388608 | 0 16777216 | 0 33554432 | 0 67108864 | 0 134217728 | 0 268435456 | 0 536870912 | 0 1073741824 | 0 2147483648 | 0 4294967296 |@@@@@ 2 8589934592 | 0 17179869184 |@@ 1 34359738368 | 0 condition variable value -------------- Distribution ------------ count 32768 | 0 65536 | 122 131072 |@@@@@ 1579 262144 |@ 340 524288 | 268 1048576 |@@@ 1028 2097152 |@@@ 1007 4194304 |@@@ 1176 8388608 |@@@@ 1257 16777216 |@@@@@@@@@@@@@@ 4385 33554432 | 295 67108864 | 157 134217728 | 96 268435456 | 48 536870912 | 144 1073741824 | 10 2147483648 | 22 4294967296 | 18 8589934592 | 5 17179869184 | 6 34359738368 | 4 68719476736 | 0 |