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 |
Wenn eine CPU in den Ruhezustand übergeht, sucht der Dispatcher nach Arbeit in den Warteschlangen anderer (belegter) CPUs. Im nächsten Beispiel soll anhand des Prüfpunkts dequeue beobachtet werden, wie oft und von welchen CPUs Anwendungen verschoben werden:
#pragma D option quiet sched:::dequeue /args[2]->cpu_id != --1 && cpu != args[2]->cpu_id && (curlwpsinfo->pr_flag & PR_IDLE)/ { @[stringof(args[1]->pr_fname), args[2]->cpu_id] = lquantize(cpu, 0, 100); } END { printa("%s stolen from CPU %d by:\n%@d\n", @); }
Der letzte Teil der Ausgabe, die Sie erhalten, wenn Sie dieses Skript auf einem System mit vier CPUs ausführen, lautet etwa:
# dtrace -s ./whosteal.d ^C ... nscd stolen from CPU 1 by: value -------------- Distribution ------------ count 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 28 3 | 0 snmpd stolen from CPU 1 by: value -------------- Distribution ------------ count < 0 | 0 0 |@ 1 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 31 3 |@@ 2 4 | 0 sched stolen from CPU 1 by: value -------------- Distribution ------------ count < 0 | 0 0 |@@ 3 1 | 0 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 36 3 |@@@@ 5 4 | 0 |
Anstatt festzustellen, welche CPUs welche Arbeit übernommen haben, möchten Sie aber möglicherweise wissen, auf welchen CPUs Prozesse und Threads auf ihre Ausführung warten. Diese Frage können wir mit einer Kombination aus den Prüfpunkten enqueue und dequeue beantworten:
sched:::enqueue { self->ts = timestamp; } sched:::dequeue /self->ts/ { @[args[2]->cpu_id] = quantize(timestamp - self->ts); self->ts = 0; }
Wenn Sie das obige Skript einige Sekunden lang ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# dtrace -s ./qtime.d dtrace: script './qtime.d' matched 5 probes ^C -1 value -------------- Distribution ------------ count 4096 | 0 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 16384 | 0 0 value -------------- Distribution ------------ count 1024 | 0 2048 |@@@@@@@@@@@@@@@ 262 4096 |@@@@@@@@@@@@@ 227 8192 |@@@@@ 87 16384 |@@@ 54 32768 | 7 65536 | 9 131072 | 1 262144 | 5 524288 | 4 1048576 | 2 2097152 | 0 4194304 | 0 8388608 | 0 16777216 | 1 33554432 | 2 67108864 | 2 134217728 | 0 268435456 | 0 536870912 | 0 1073741824 | 1 2147483648 | 1 4294967296 | 0 1 value -------------- Distribution ------------ count 1024 | 0 2048 |@@@@ 49 4096 |@@@@@@@@@@@@@@@@@@@@ 241 8192 |@@@@@@@ 91 16384 |@@@@ 55 32768 | 7 65536 | 3 131072 | 2 262144 | 1 524288 | 0 1048576 | 0 2097152 | 0 4194304 | 0 8388608 | 0 16777216 | 0 33554432 | 3 67108864 | 1 134217728 | 4 268435456 | 2 536870912 | 0 1073741824 | 3 2147483648 | 2 4294967296 | 0 |
Beachten Sie die Werte ungleich Null am Ende der Beispielausgabe. Wie diese Datenpunkte zeigen, kam es auf beiden CPUs mehrmals vor, dass ein Thread mehrere Sekunden lang in der Ausführungswarteschlange stand.
Möglicherweise interessiert Sie aber nicht so sehr die jeweilige Wartezeit, sondern die Länge der Ausführungswarteschlange im Verlauf der Zeit. Mit den Prüfpunkten enqueue und dequeue können Sie einen assoziativen Vektor zum Ermitteln der Warteschlangenlänge einrichten:
sched:::enqueue { this->len = qlen[args[2]->cpu_id]++; @[args[2]->cpu_id] = lquantize(this->len, 0, 100); } sched:::dequeue /qlen[args[2]->cpu_id]/ { qlen[args[2]->cpu_id]—; }
Wenn Sie das obige Skript ungefähr 30 Sekunden lang auf einem großteilig im Ruhezustand befindlichen Laptop-System ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# dtrace -s ./qlen.d dtrace: script './qlen.d' matched 5 probes ^C 0 value -------------- Distribution ------------ count < 0 | 0 0 |@@@@@@@@@@@@@@@@@@@@@@@@@ 110626 1 |@@@@@@@@@ 41142 2 |@@ 12655 3 |@ 5074 4 | 1722 5 | 701 6 | 302 7 | 63 8 | 23 9 | 12 10 | 24 11 | 58 12 | 14 13 | 3 14 | 0 |
Die Ausgabe entspricht grob den allgemeinen Erwartungen für ein System im Ruhezustand: Wenn ein ausführbarer Thread in die Warteschlange gestellt wird, ist die Warteschlange meistens sehr kurz (drei oder weniger Threads lang). Da sich aber das System großteilig im Ruhezustand befand, fallen die außergewöhnlichen Datenpunkte am Ende der Tabelle als eher unerwartet auf. Weshalb war zum Beispiel die Ausführungswarteschlange länger als 13 ausführbare Threads? Um dieser Frage auf den Grund zu gehen, könnten wir ein D-Skript schreiben, das den Inhalt der Ausführungswarteschlange anzeigt, wenn diese eine gewisse Länge erreicht. Das Problem ist allerdings recht komplex, da D-Aktivierungen nicht über Datenstrukturen wiederholt und folglich nicht einfach über der gesamten Ausführungswarteschlange wiederholt werden können. Selbst wenn dies möglich wäre, müssten Abhängigkeiten von den kernelinternen Datenstrukturen vermieden werden.
Für diese Art Skript würden wir die Prüfpunkte enqueue und dequeue aktivieren und sowohl Spekulationen als auch assoziative Vektoren verwenden. Immer wenn ein Thread in die Warteschlange gestellt wird, erhöht das Skript die Länge der Warteschlange und zeichnet die Zeitmarke in einem assoziativen Vektor mit Schlüssel des Threads auf. In diesem Fall kann keine thread-lokale Variable verwendet werden, da ein Thread auch durch einen anderen Thread in die Warteschlange gestellt werden kann. Das Skript überprüft dann, ob die Warteschlangenlänge das Maximum übersteigt. ist dies der Fall, beginnt das Skript eine neue Spekulation und zeichnet die Zeitmarke und das neue Maximum auf. Wenn dann ein Thread aus der Warteschlange gelöscht wird, vergleicht das Skript die Zeitmarke der Einreihung in die Warteschlange mit derjenigen der maximalen Länge: Wenn der Thread vor der Zeitmarke der maximalen Länge in die Warteschlange gestellt wurde, befand er sich bereits in der Warteschlange, als die maximale Länge aufgezeichnet wurde. In diesem Fall führt das Skript eine spekulative Ablaufverfolgung der Thread-Informationen durch. Wenn der Kernel den letzten zum Zeitpunkt der maximalen Länge eingereihten Thread aus der Warteschlange löscht, übergibt das Skript die Spekulationsdaten. Das Skript sieht wie folgt aus:
#pragma D option quiet #pragma D option nspec=4 #pragma D option specsize=100k int maxlen; int spec[int]; sched:::enqueue { this->len = ++qlen[this->cpu = args[2]->cpu_id]; in[args[0]->pr_addr] = timestamp; } sched:::enqueue /this->len > maxlen && spec[this->cpu]/ { /* * There is already a speculation for this CPU. We just set a new * record, so we'll discard the old one. */ discard(spec[this->cpu]); } sched:::enqueue /this->len > maxlen/ { /* * We have a winner. Set the new maximum length and set the timestamp * of the longest length. */ maxlen = this->len; longtime[this->cpu] = timestamp; /* * Now start a new speculation, and speculatively trace the length. */ this->spec = spec[this->cpu] = speculation(); speculate(this->spec); printf("Run queue of length %d:\n", this->len); } sched:::dequeue /(this->in = in[args[0]->pr_addr]) && this->in <= longtime[this->cpu = args[2]->cpu_id]/ { speculate(spec[this->cpu]); printf(" %d/%d (%s)\n", args[1]->pr_pid, args[0]->pr_lwpid, stringof(args[1]->pr_fname)); } sched:::dequeue /qlen[args[2]->cpu_id]/ { in[args[0]->pr_addr] = 0; this->len = --qlen[args[2]->cpu_id]; } sched:::dequeue /this->len == 0 && spec[this->cpu]/ { /* * We just processed the last thread that was enqueued at the time * of longest length; commit the speculation, which by now contains * each thread that was enqueued when the queue was longest. */ commit(spec[this->cpu]); spec[this->cpu] = 0; }
Die Ausführung des obigen Skripts auf demselben Einzelprozessor-Laptop erzeugt eine Ausgabe wie in folgendem Beispiel:
# dtrace -s ./whoqueue.d Run queue of length 3: 0/0 (sched) 0/0 (sched) 101170/1 (dtrace) Run queue of length 4: 0/0 (sched) 100356/1 (Xsun) 100420/1 (xterm) 101170/1 (dtrace) Run queue of length 5: 0/0 (sched) 0/0 (sched) 100356/1 (Xsun) 100420/1 (xterm) 101170/1 (dtrace) Run queue of length 7: 0/0 (sched) 100221/18 (nscd) 100221/17 (nscd) 100221/16 (nscd) 100221/13 (nscd) 100221/14 (nscd) 100221/15 (nscd) Run queue of length 16: 100821/1 (xterm) 100768/1 (xterm) 100365/1 (fvwm2) 101118/1 (xterm) 100577/1 (xterm) 101170/1 (dtrace) 101020/1 (xterm) 101089/1 (xterm) 100795/1 (xterm) 100741/1 (xterm) 100710/1 (xterm) 101048/1 (xterm) 100697/1 (MozillaFirebird-) 100420/1 (xterm) 100394/1 (xterm) 100368/1 (xterm) ^C |
Die Ausgabe zeigt auf, dass die langen Ausführungswarteschlangen auf viele ausführbare xterm-Prozesse zurückzuführen sind. Dieses Experiment fiel mit einem Wechsel des virtuellen Desktops zusammen. Die Ergebnisse lassen sich deshalb wahrscheinlich durch eine Art der Verarbeitung von X-Ereignissen erklären.
Das letzte Beispiel unter enqueue und dequeue hat gezeigt, dass ausführbare xterm-Prozesse zu besonders langen Ausführungswarteschlangen geführt haben. Es ist denkbar, dass diese Beobachtung auf einen Wechsel des virtuellen Desktops zurückzuführen ist. Mit dem Prüfpunkt wakeup können Sie diese Hypothese untersuchen, indem Sie ermitteln, wer die xterm-Prozesse wann aufweckt:
#pragma D option quiet dtrace:::BEGIN { start = timestamp; } sched:::wakeup /stringof(args[1]->pr_fname) == "xterm"/ { @[execname] = lquantize((timestamp - start) / 1000000000, 0, 10); } profile:::tick-1sec /++x == 10/ { exit(0); }
Um dieser Frage nachzugehen, führen Sie also das obige Skript aus, warten rund fünf Sekunden und wechseln den Desktop genau einmal. Wenn das hohe Aufkommen ausführbarer xterm-Prozesse auf den Wechsel des virtuellen Desktops zurückzuführen ist, sollte die Ausgabe an der 5-Sekunden-Marke eine hohe Aufweck-Aktivität zeigen.
# dtrace -s ./xterm.d Xsun value -------------- Distribution ------------ count 4 | 0 5 |@ 1 6 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 32 7 | 0 |
In der Ausgabe ist zu sehen, dass der X-Server zu dem Zeitpunkt, zu dem Sie den virtuellen Desktop gewechselt haben, gehäuft xterm-Prozesse aufweckt. Wenn Sie die Interaktion zwischen dem X-Server und den xterm-Prozessen erkunden möchten, könnten Sie die Benutzer-Stack-Aufzeichnungen aggregieren, wenn der X-Server den Prüfpunkt wakeup auslöst.
Um Client-Server-Systeme wie das X-Fenstersystem zu verstehen, muss man zunächst die Clients verstehen, für die der Server arbeitet. Diese Frage ist mit herkömmlichen Tools für die Leistungsanalyse nicht leicht zu beantworten. Bei Modellen, in welchen ein Client eine Meldung an den Server sendet und in Erwartung der Verarbeitung durch den Server schläft, können Sie jedoch den Prüfpunkt wakeup einsetzen, um den Client zu ermitteln, für den die Anforderung läuft. Das folgende Beispiel zeigt dies:
self int last; sched:::wakeup /self->last && args[0]->pr_stype == SOBJ_CV/ { @[stringof(args[1]->pr_fname)] = sum(vtimestamp - self->last); self->last = 0; } sched:::wakeup /execname == "Xsun" && self->last == 0/ { self->last = vtimestamp; }
Die Ausführung des obigen Skripts erzeugt eine Ausgabe wie in folgendem Beispiel:
dtrace -s ./xwork.d dtrace: script './xwork.d' matched 14 probes ^C xterm 9522510 soffice.bin 9912594 fvwm2 100423123 MozillaFirebird 312227077 acroread 345901577 |
An dieser Ausgabe erkennen wir, dass ein Großteil der Xsun-Arbeit für die Prozesse acroread, MozillaFirebird und in geringerem Maße auch für fvwm2 geleistet wird. Beachten Sie, dass das Skript nur wakeups von Synchronisierungsobjekten in Form von Bedingungsvariablen (SOBJ_CV) untersucht. Wie aus Tabelle 25–4 hervorgeht, werden Bedingungsvariablen in der Regel dort als Synchronisierungsobjekte eingesetzt, wo aus anderen Gründen als einem Zugriff auf einen gemeinsam genutzten Datenbereich eine Synchronisierung erforderlich ist. Im Fall des X-Servers wartet ein Client auf Daten in einer Pipe, indem er sich an einer Bedingungsvariable schlafen legt.
Zusätzlich können Sie wie im nächsten Beispiel den Prüfpunkt sleep neben wakeup verwenden, um nachzuvollziehen, welche Anwendungen durch welche anderen Anwendungen wie lang blockiert werden:
#pragma D option quiet sched:::sleep /!(curlwpsinfo->pr_flag & PR_ISSYS) && curlwpsinfo->pr_stype == SOBJ_CV/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { @[stringof(args[1]->pr_fname), execname] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } END { printa("%s sleeping on %s:\n%@d\n", @); }
Das Ende der Ausgabe, die Sie erhalten, wenn Sie das Beispielskript einige Sekunden auf einem Desktop-System ausführen, sieht ungefähr wie folgt aus:
# dtrace -s ./whofor.d ^C ... xterm sleeping on Xsun: value -------------- Distribution ------------ count 131072 | 0 262144 | 12 524288 | 2 1048576 | 0 2097152 | 5 4194304 |@@@ 45 8388608 | 1 16777216 | 9 33554432 |@@@@@ 83 67108864 |@@@@@@@@@@@ 164 134217728 |@@@@@@@@@@ 147 268435456 |@@@@ 56 536870912 |@ 17 1073741824 | 9 2147483648 | 1 4294967296 | 3 8589934592 | 1 17179869184 | 0 fvwm2 sleeping on Xsun: value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@@@@@@@@@@@@@@@@@@ 67 131072 |@@@@@ 16 262144 |@@ 6 524288 |@ 3 1048576 |@@@@@ 15 2097152 | 0 4194304 | 0 8388608 | 1 16777216 | 0 33554432 | 0 67108864 | 1 134217728 | 0 268435456 | 0 536870912 | 1 1073741824 | 1 2147483648 | 2 4294967296 | 2 8589934592 | 2 17179869184 | 0 34359738368 | 2 68719476736 | 0 syslogd sleeping on syslogd: value -------------- Distribution ------------ count 17179869184 | 0 34359738368 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 68719476736 | 0 MozillaFirebird sleeping on MozillaFirebird: value -------------- Distribution ------------ count 65536 | 0 131072 | 3 262144 |@@ 14 524288 | 0 1048576 |@@@ 18 2097152 | 0 4194304 | 0 8388608 | 1 16777216 | 0 33554432 | 1 67108864 | 3 134217728 |@ 7 268435456 |@@@@@@@@@@ 53 536870912 |@@@@@@@@@@@@@@ 78 1073741824 |@@@@ 25 2147483648 | 0 4294967296 | 0 8589934592 |@ 7 17179869184 | 0 |
Es könnte interessant sein, zu verstehen, wie und weshalb MozillaFirebird durch sich selbst blockiert wird. Um diese Frage zu beantworten, ändern Sie das obige Skript wie folgt ab:
#pragma D option quiet sched:::sleep /execname == "MozillaFirebird" && curlwpsinfo->pr_stype == SOBJ_CV/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /execname == "MozillaFirebird" && bedtime[args[0]->pr_addr]/ { @[args[1]->pr_pid, args[0]->pr_lwpid, pid, curlwpsinfo->pr_lwpid] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { bedtime[args[0]->pr_addr] = 0; } END { printa("%d/%d sleeping on %d/%d:\n%@d\n", @); }
Wenn Sie dieses geänderte Skript einige Sekunden lang ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# dtrace -s ./firebird.d ^C 100459/1 sleeping on 100459/13: value -------------- Distribution ------------ count 262144 | 0 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 1048576 | 0 100459/13 sleeping on 100459/1: value -------------- Distribution ------------ count 16777216 | 0 33554432 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 67108864 | 0 100459/1 sleeping on 100459/2: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@ 5 65536 |@ 2 131072 |@@@@@ 6 262144 | 1 524288 |@ 2 1048576 | 0 2097152 |@@ 3 4194304 |@@@@ 5 8388608 |@@@@@@@@ 9 16777216 |@@@@@ 6 33554432 |@@ 3 67108864 | 0 100459/1 sleeping on 100459/5: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@ 12 65536 |@@ 5 131072 |@@@@@@ 15 262144 | 1 524288 | 1 1048576 | 2 2097152 |@ 4 4194304 |@@@@@ 13 8388608 |@@@ 8 16777216 |@@@@@ 13 33554432 |@@ 6 67108864 |@@ 5 134217728 |@ 4 268435456 | 0 536870912 | 1 1073741824 | 0 100459/2 sleeping on 100459/1: value -------------- Distribution ------------ count 16384 | 0 32768 |@@@@@@@@@@@@@@ 11 65536 | 0 131072 |@@ 2 262144 | 0 524288 | 0 1048576 |@@@@ 3 2097152 |@ 1 4194304 |@@ 2 8388608 |@@ 2 16777216 |@ 1 33554432 |@@@@@@ 5 67108864 | 0 134217728 | 0 268435456 | 0 536870912 |@ 1 1073741824 |@ 1 2147483648 |@ 1 4294967296 | 0 100459/5 sleeping on 100459/1: value -------------- Distribution ------------ count 16384 | 0 32768 | 1 65536 | 2 131072 | 4 262144 | 7 524288 | 1 1048576 | 5 2097152 | 10 4194304 |@@@@@@ 77 8388608 |@@@@@@@@@@@@@@@@@@@@@@@ 270 16777216 |@@@ 43 33554432 |@ 20 67108864 |@ 14 134217728 | 5 268435456 | 2 536870912 | 1 1073741824 | 0 |
Auch die Leistung von Door-Servern wie zum Beispiel des Cache-Dämons des Namensdienstes kann, wie das folgende Beispiel zeigt, mit den Prüfpunkten sleep und wakeup beobachtet werden:
sched:::sleep /curlwpsinfo->pr_stype == SOBJ_SHUTTLE/ { bedtime[curlwpsinfo->pr_addr] = timestamp; } sched:::wakeup /execname == "nscd" && bedtime[args[0]->pr_addr]/ { @[stringof(curpsinfo->pr_fname), stringof(args[1]->pr_fname)] = quantize(timestamp - bedtime[args[0]->pr_addr]); bedtime[args[0]->pr_addr] = 0; } sched:::wakeup /bedtime[args[0]->pr_addr]/ { bedtime[args[0]->pr_addr] = 0; }
Das Ende der Ausgabe, die Sie erhalten, wenn Sie dieses Skript auf einem großen Mail-Server ausführen, sieht etwa wie folgt aus:
imapd value -------------- Distribution ------------ count 16384 | 0 32768 | 2 65536 |@@@@@@@@@@@@@@@@@ 57 131072 |@@@@@@@@@@@ 37 262144 | 3 524288 |@@@ 11 1048576 |@@@ 10 2097152 |@@ 9 4194304 | 1 8388608 | 0 mountd value -------------- Distribution ------------ count 65536 | 0 131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 49 262144 |@@@ 6 524288 | 1 1048576 | 0 2097152 | 0 4194304 |@@@@ 7 8388608 |@ 3 16777216 | 0 sendmail value -------------- Distribution ------------ count 16384 | 0 32768 |@ 18 65536 |@@@@@@@@@@@@@@@@@ 205 131072 |@@@@@@@@@@@@@ 154 262144 |@ 23 524288 | 5 1048576 |@@@@ 50 2097152 | 7 4194304 | 5 8388608 | 2 16777216 | 0 automountd value -------------- Distribution ------------ count 32768 | 0 65536 |@@@@@@@@@@ 22 131072 |@@@@@@@@@@@@@@@@@@@@@@@ 51 262144 |@@ 6 524288 | 1 1048576 | 0 2097152 | 2 4194304 | 2 8388608 | 1 16777216 | 1 33554432 | 1 67108864 | 0 134217728 | 0 268435456 | 1 536870912 | 0 |
Möglicherweise fallen Ihnen die ungewöhnlichen Datenpunkte für automountd oder der dauerhafte Datenpunkt bei über einer Millisekunde für sendmail als interessant auf. Mithilfe von zusätzlichen Prädikaten, die Sie in das obige Skript einbauen, können Sie die Ursachen für jedes außergewöhnliche oder anomale Ergebnis weiter einkreisen.
Da Solaris ein präemptives System ist, werden Threads mit niedriger Priorität unterbrochen, indem Threads mit höherer Priorität CPU-Zeit zugeteilt wird. Diese Vorrangunterbrechung kann zu einer bedeutenden Latenz des Threads mit der niedrigeren Priorität führen. Deshalb ist es mitunter hilfreich, zu wissen, welche Threads durch welche anderen unterbrochen werden. Das folgende Beispiel zeigt, wie sich diese Informationen mithilfe der Prüfpunkte preempt und remain-cpu anzeigen lassen:
#pragma D option quiet sched:::preempt { self->preempt = 1; } sched:::remain-cpu /self->preempt/ { self->preempt = 0; } sched:::off-cpu /self->preempt/ { /* * If we were told to preempt ourselves, see who we ended up giving * the CPU to. */ @[stringof(args[1]->pr_fname), args[0]->pr_pri, execname, curlwpsinfo->pr_pri] = count(); self->preempt = 0; } END { printf("%30s %3s %30s %3s %5s\n", "PREEMPTOR", "PRI", "PREEMPTED", "PRI", "#"); printa("%30s %3d %30s %3d %5@d\n", @); }
Wenn Sie das obige Skript einige Sekunden lang auf einem Desktop-System ausführen, erhalten Sie eine Ausgabe wie in folgendem Beispiel:
# dtrace -s ./whopreempt.d ^C PREEMPTOR PRI PREEMPTED PRI # sched 60 Xsun 53 1 xterm 59 Xsun 53 1 MozillaFirebird 57 Xsun 53 1 mpstat 100 fvwm2 59 1 sched 99 MozillaFirebird 57 1 sched 60 dtrace 30 1 mpstat 100 Xsun 59 2 sched 60 Xsun 54 2 sched 99 sched 60 2 fvwm2 59 Xsun 44 2 sched 99 Xsun 44 2 sched 60 xterm 59 2 sched 99 Xsun 53 2 sched 99 Xsun 54 3 sched 60 fvwm2 59 3 sched 60 Xsun 59 3 sched 99 Xsun 59 4 fvwm2 59 Xsun 54 8 fvwm2 59 Xsun 53 9 Xsun 59 MozillaFirebird 57 10 sched 60 MozillaFirebird 57 14 MozillaFirebird 57 Xsun 44 16 MozillaFirebird 57 Xsun 54 18 |
Die Vorrangunterbrechung basiert auf Prioritäten. Aus diesem Grund kann sich auch die Beobachtung der Veränderung von Prioritäten über einen bestimmten Zeitraum als interessant erweisen. Im nächsten Beispiel werden diese Informationen mithilfe des Prüfpunkts change-pri angezeigt:
sched:::change-pri { @[stringof(args[0]->pr_clname)] = lquantize(args[2] - args[0]->pr_pri, -50, 50, 5); }
Das Beispielskript erfasst den Grad, auf den die Priorität angehoben oder herabgesetzt wird, und aggregiert die Daten nach Scheduling-Klasse. Die Ausführung des obigen Skripts erzeugt eine Ausgabe wie in folgendem Beispiel:
# dtrace -s ./pri.d dtrace: script './pri.d' matched 10 probes ^C IA value -------------- Distribution ------------ count < -50 | 20 -50 |@ 38 -45 | 4 -40 | 13 -35 | 12 -30 | 18 -25 | 18 -20 | 23 -15 | 6 -10 |@@@@@@@@ 201 -5 |@@@@@@ 160 0 |@@@@@ 138 5 |@ 47 10 |@@ 66 15 |@ 36 20 |@ 26 25 |@ 28 30 | 18 35 | 22 40 | 8 45 | 11 >= 50 |@ 34 TS value -------------- Distribution ------------ count -15 | 0 -10 |@ 1 -5 |@@@@@@@@@@@@ 7 0 |@@@@@@@@@@@@@@@@@@@@ 12 5 | 0 10 |@@@@@ 3 15 | 0 |
Die Ausgabe zeigt die Manipulation der Priorität für die interaktive (IA) Scheduling-Klasse. Anstelle der Manipulation der Priorität möchten Sie aber womöglich die Prioritätswerte eines bestimmten Prozesses und Threads im Verlauf der Zeit feststellen. Im nächsten Skript werden diese Informationen mithilfe des Prüfpunkts change-pri angezeigt:
#pragma D option quiet BEGIN { start = timestamp; } sched:::change-pri /args[1]->pr_pid == $1 && args[0]->pr_lwpid == $2/ { printf("%d %d\n", timestamp - start, args[2]); } tick-1sec /++n == 5/ { exit(0); }
Um die Änderung der Priorität im Verlauf der Zeit zu sehen, geben Sie den folgenden Befehl in ein Fenster ein:
$ echo $$ 139208 $ while true ; do let i=0 ; done |
Führen Sie in einem anderen Fenster das Skript aus und leiten Sie die Ausgabe in eine Datei um:
# dtrace -s ./pritime.d 139208 1 > /tmp/pritime.out # |
Die dabei generierte Datei /tmp/pritime.out kann als Eingabe für Plotting-Software verwendet werden und ermöglicht so die grafische Anzeige der Prioritätsänderung im Verlauf der Zeit. gnuplot ist auf der Solaris Freeware Companion-CD als frei verfügbare Plotting-Software enthalten. gnuplot wird standardmäßig unter /opt/sfw/bin installiert.
In Solaris kommt eine tick-basierte CPU-Abrechnung zum Einsatz. Dabei wird in einem festgelegten Intervall ein Systemuhr-Interrupt ausgelöst und den zum Zeitpunkt des Ticks laufenden Threads und Prozessen CPU-Zeit zugewiesen. Das nächste Beispiel veranschaulicht, wie sich diese Zuweisung mit dem Prüfpunkt tick beobachten lässt:
# dtrace -n sched:::tick'{@[stringof(args[1]->pr_fname)] = count()}' ^C arch 1 sh 1 sed 1 echo 1 ls 1 FvwmAuto 1 pwd 1 awk 2 basename 2 expr 2 resize 2 tput 2 uname 2 fsflush 2 dirname 4 vim 9 fvwm2 10 ksh 19 xterm 21 Xsun 93 MozillaFirebird 260 |
Die Systemuhrfrequenz ist von Betriebssystem zu Betriebssystem verschieden, bewegt sich aber im Allgemeinen zwischen 25 und 1024 Hertz. Unter Solaris ist dieser Systemtakt anpassbar, beträgt aber standardmäßig 100 Hertz.
Der Prüfpunkt tick wird nur ausgelöst, wenn die Systemuhr einen ausführbaren Thread entdeckt. Damit der Systemtakt anhand des Prüfpunkts tick beobachtet werden kann, muss ein stets ausführbarer Thread vorliegen. Erzeugen Sie in einem Fenster wie folgt eine Shell-Schleife:
$ while true ; do let i=0 ; done |
Führen Sie in einem anderen Fenster das folgende Skript aus:
uint64_t last[int]; sched:::tick /last[cpu]/ { @[cpu] = min(timestamp - last[cpu]); } sched:::tick { last[cpu] = timestamp; }
# dtrace -s ./ticktime.d dtrace: script './ticktime.d' matched 2 probes ^C 0 9883789 |
Das geringste Intervall beträgt 9,8 Millisekunden, was darauf hindeutet, dass der Standardtakt 10 Millisekunden (100 Hertz) beträgt. Der beobachtete Mindestwert liegt aufgrund von Jitter ein wenig unter 10 Millisekunden.
Ein Mangel der tick-basierten Abrechnung besteht darin, dass die die Abrechnung durchführende Systemuhr häufig auch für das Dispatchen zeitorientierter Scheduling-Aktivitäten verantwortlich ist. Folglich rechnet das System für Threads, die mit jedem Uhr-Tick (d. h. alle 10 Millisekunden) einen gewissen Umfang an Arbeit leisten sollen, je nachdem, ob die Abrechnung vor oder nach dem Dispatchen der zeitorientierten Scheduling-Aktivität erfolgt, entweder zu viel oder zu wenig Zeit ab. Unter Solaris erfolgt die Abrechnung vor dem zeitorientierten Dispatchen. Daraus folgt, dass das System Threads, die in einem regelmäßigen Intervall ausgeführt werden, zu niedrig abrechnet. Wenn solche Threads kürzer als die Dauer eines Uhr-Tick-Intervalls ausfallen, können sie sich erfolgreich hinter dem Uhr-Tick „verbergen“. Das folgende Beispiel zeigt, in welchem Umfang derartige Threads im System vorkommen:
sched:::tick, sched:::enqueue { @[probename] = lquantize((timestamp / 1000000) % 10, 0, 10); }
Die Ausgabe des Beispielskripts zeigt zwei Verteilungen des Versatzes in Millisekunden innerhalb eines Intervalls von zehn Millisekunden - eine für den Prüfpunkt tick und eine weitere für enqueue:
# dtrace -s ./tick.d dtrace: script './tick.d' matched 4 probes ^C tick value -------------- Distribution ------------ count 6 | 0 7 |@ 3 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 79 9 | 0 enqueue value -------------- Distribution ------------ count < 0 | 0 0 |@@ 267 1 |@@ 300 2 |@@ 259 3 |@@ 291 4 |@@@ 360 5 |@@ 305 6 |@@ 295 7 |@@@@ 522 8 |@@@@@@@@@@@@ 1315 9 |@@@ 337 |
Das Ausgabehistogramm tick zeigt, dass der Uhr-Tick mit einem Versatz von 8 Millisekunden ausgelöst wird. Wenn das Scheduling unabhängig von dem Uhr-Tick erfolgen würde, wäre die Ausgabe für enqueue gleichmäßig über das Intervall von zehn Millisekunden verteilt. Wir sehen in der Ausgabe jedoch an demselben Versatz von 8 Millisekunden eine Spitze, die darauf hinweist, dass für einige Threads im System sehr wohl ein zeitorientiertes Scheduling stattfindet.