Welche CPUs führen Threads aus und wie lange? Dies ist eine der Fragen, auf die man häufig gerne eine Antwort hätte. Mit den Prüfpunkten on-cpu und off-cpu lässt sich diese Frage, wie das folgende Beispiel zeigt, auf systemweiter Basis einfach beantworten:
sched:::on-cpu { self->ts = timestamp; } sched:::off-cpu /self->ts/ { @[cpu] = quantize(timestamp - self->ts); self->ts = 0; }
Die Ausführung des obigen Skripts erzeugt eine Ausgabe wie in folgendem Beispiel:
# 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 |
Die obige Ausgabe zeigt, dass auf CPU 1 Threads über einen Zeitraum von weniger als 100 Mikrosekunden oder für ca. 10 Millisekunden laufen. Zwischen den zwei Datengruppen ist im Histogramm eine deutliche Lücke zu erkennen. Sie möchten vielleicht auch wissen, welche CPUs einen bestimmten Prozess ausführen. Auch diese Frage können Sie mit den Prüfpunkten on-cpu und off-cpu beantworten. Das folgende Skript zeigt, welche CPUs eine angegebene Anwendung über einen Zeitraum von zehn Sekunden ausführen:
#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", @); }
Wenn Sie dieses Skript auf einem großen Mail-Server ausführen und den IMAP-Dämon angeben, erhalten Sie eine ähnliche Ausgabe wie diese:
# 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 |
In Solaris wird bei der Auswahl einer CPU, auf der Threads ausgeführt werden sollen, die Schlafzeit der Threads berücksichtigt: Threads, die seit kürzerer Zeit schlafen, migrieren in der Regel eher nicht. Mit den Prüfpunkten on-cpu und off-cpu lässt sich dieses Verhalten beobachten:
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; }
Wenn Sie das obige Skript ungefähr 30 Sekunden lang ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# 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 |
Aus der Beispielausgabe geht hervor, dass sehr viel häufiger keine Migration stattfindet. Auch zeigt sie, dass eine Migration bei längeren Schlafzeiten wahrscheinlicher ist. Die Verteilungen im Bereich unter 100 Millisekunden fallen deutlich unterschiedlich aus, gleichen sich aber mit zunehmender Schlafdauer immer näher an. Dieses Ergebnis könnte man dahin gehend interpretieren, dass die Schlafzeit bei der Scheduling-Entscheidung keine Rolle mehr spielt, sobald ein bestimmter Schwellwert überschritten ist.
Unser letztes Beispiel für die Prüfpunkte off-cpu und on-cpu demonstriert deren Einsatz gemeinsam mit dem Feld pr_stype, um festzustellen, weshalb und wie lange Threads schlafen:
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; }
Wenn Sie das obige Skript einige Sekunden lang ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# 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 |