Beispiele
on-cpu und off-cpu
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
|
enqueue und dequeue
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.
sleep und wakeup
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.
preempt, remain-cpu
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
|
change-pri
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.
tick
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.
- © 2010, Oracle Corporation and/or its affiliates