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.
- © 2010, Oracle Corporation and/or its affiliates