Kapitel 33 Ablaufverfolgung von Benutzerprozessen
DTrace ist ein äußerst leistungsfähiges Tool für die Analyse des Verhaltens von Benutzerprozessen. Zum Debuggen, Analysieren von Leistungsproblemen oder einfach zum Nachvollziehen des Verhaltens komplexer Anwendungen erweist sich DTrace als unschätzbare Hilfe. Dieses Kapitel konzentriert sich auf die DTrace-Einrichtungen für die Ablaufverfolgung der Benutzerprozesstätigkeit und enthält Beispiele für deren Verwendung.
Die Subroutinen copyin() und copyinstr()
Wie DTrace mit Prozessen interagiert, unterscheidet sich geringfügig von den meisten herkömmlichen Debuggern oder Beobachtungstools. Viele dieser Hilfsmittel werden scheinbar innerhalb des Bereichs des Prozesses ausgeführt und lassen eine direkte Dereferenzierung von Zeigern auf Programmvariablen durch Benutzer zu. Anstatt scheinbar innerhalb oder als Bestandteil des Prozesses selbst, werden DTrace-Prüfpunkte im Solaris-Kernel ausgeführt. Für den Zugriff auf Prozessdaten müssen Prüfpunkte die Prozessdaten mithilfe der Subroutinen copyin() oder copyinstr() in den Adressraum des Kernels kopieren.
Betrachten wir beispielsweise den folgenden write(2)-Systemaufruf:
ssize_t write(int fd, const void *buf, size_t nbytes);
Das folgende D-Programm demonstriert einen falschen Versuch, den Inhalt einer dem write(2)-Systemaufruf übergebenen Zeichenkette auszugeben:
syscall::write:entry
{
printf("%s", stringof(arg1)); /* incorrect use of arg1 */
}
Wenn Sie versuchen, dieses Skript auszuführen, erzeugt DTrace ähnliche Fehlermeldungen wie in diesem Beispiel:
dtrace: error on enabled probe ID 1 (ID 37: syscall::write:entry): \
invalid address (0x10038a000) in action #1
|
Bei der Variable arg1, die den Wert des Parameters Puffer enthält, handelt es sich um eine Adresse im Speicher des Prozesses, der den Systemaufruf durchführt. Die Zeichenkette an dieser Adresse lesen wir mit der Subroutine copyinstr() und zeichnen das Ergebnis mit der Aktion printf() auf:
syscall::write:entry
{
printf("%s", copyinstr(arg1)); /* correct use of arg1 */
Die Ausgabe dieses Skripts zeigt alle Zeichenketten, die an den write(2)-Systemaufruf übergeben werden. Gelegentlich kann jedoch eine unbrauchbare Ausgabe wie in diesem Beispiel erzeugt werden:
0 37 write:entry mada��� |
Die Subroutine copyinstr() wirkt auf ein Eingabeargument, die Benutzeradresse einer auf Null endenden ASCII-Zeichenkette. Dem write(2)-Systemaufruf übergebene Puffer beziehen sich jedoch möglicherweise nicht auf ASCII-Zeichenketten, sondern auf Binärdaten. Damit nur so viel von der Zeichenkette ausgegeben wird, wie der Aufrufer beabsichtigt hat, verwenden Sie die Subroutine copyin(), die als zweites Argument eine Größe annimmt:
syscall::write:entry
{
printf("%s", stringof(copyin(arg1, arg2)));
}
Beachten Sie, dass DTrace den Operator stringof benötigt, um die mit copyin() abgerufenen Benutzerdaten in eine Zeichenkette umzuwandeln. Wenn Sie&;copyinstr verwenden, ist stringof() nicht erforderlich, da diese Funktion stets den Typ string zurückgibt.
Vermeiden von Fehlern
Die Subroutinen copyin() und copyinstr() können nicht aus noch „unberührten“ Benutzeradressen lesen. Das heißt, dass selbst eine gültige Adresse einen Fehler verursachen kann, wenn die Speicherseite, die diese Adresse enthält, noch nicht durch einen Seitenfehler infolge eines Zugriffs eingelagert wurde. Betrachten wir das folgende Beispiel:
# dtrace -n syscall::open:entry'{ trace(copyinstr(arg0)); }'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU ID FUNCTION:NAME
dtrace: error on enabled probe ID 2 (ID 50: syscall::open:entry): invalid address
(0x9af1b) in action #1 at DIF offset 52
|
Die Anwendung in der obigen Ausgabe funktioniert ordnungsgemäß und die Adresse in arg0 ist gültig, bezieht sich aber auf eine Seite, auf die noch nicht durch den entsprechenden Prozess zugegriffen wurde. Um dieses Problem zu umgehen, warten Sie mit der Aufzeichnung, bis Kernel oder Anwendung die Daten verwenden. Sie könnten etwa wie im nächsten Beispiel mit der Anwendung von copyinstr() warten, bis der Systemaufruf zurückkehrt:
# dtrace -n syscall::open:entry'{ self->file = arg0; }' \
-n syscall::open:return'{ trace(copyinstr(self->file)); self->file = 0; }'
dtrace: description 'syscall::open:entry' matched 1 probe
CPU ID FUNCTION:NAME
2 51 open:return /dev/null
|
Ausschalten von dtrace(1M)-Interferenzen
Wenn Sie jeden Aufruf des write(2)-Systemaufrufs verfolgen, erhalten Sie eine Kette aufeinander folgender Ausgaben. Mit jedem Aufruf von write() ruft der Befehl dtrace(1M) während der Anzeige der Ausgabe write() auf usw. Diese Rückmeldungsschleife ist ein gutes Beispiel dafür, wie der Befehl dtrace in die gewünschten Daten eingreifen kann. Die Aufzeichnung dieser unerwünschten Daten lässt sich durch ein einfaches Prädikat vermeiden:
syscall::write:entry
/pid != $pid/
{
printf("%s", stringof(copyin(arg1, arg2)));
}
Die Makrovariable $pid wird durch die Prozess-ID des Prozesses ersetzt, der die Prüfpunkte aktiviert hat. Die Variable pid enthält die Prozess-ID des Prozesses, dessen Thread auf der CPU lief, auf der der Prüfpunkt ausgelöst wurde. Das Prädikat /pid != $pid/ gewährleistet deshalb, dass das Skript keine Ereignisse in Verbindung mit der Ausführung des Skripts selbst verfolgt.
Der Provider syscall
Der Provider syscall ermöglicht die Ablaufverfolgung jedes Eintritts in einen und jeder Rückkehr von einem Systemaufruf. Systemaufrufe stellen häufig einen guten Ausgangspunkt zum Verstehen des Verhaltens eines Prozesses dar, insbesondere dann, wenn der Prozess eine lange Ausführungszeit aufweist oder lange im Kernel blockiert bleibt. Mit dem Befehl prstat(1M) lässt sich beobachten, wo Prozesse Zeit verbringen:
$ prstat -m -p 31337 PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP 13499 user1 53 44 0.0 0.0 0.0 0.0 2.5 0.0 4K 24 9K 0 mystery/6 |
Dieses Beispiel zeigt, dass der Prozess sehr viel Systemzeit verbraucht. Eine mögliche Erklärung für dieses Verhalten ist, dass der Prozess zahlreiche Systemaufrufe ausführt. Ein einfaches, in der Befehlszeile angegebenes D-Programm zeigt uns, welche Systemaufrufe am häufigsten vorkommen:
# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }'
dtrace: description 'syscall:::entry' matched 215 probes
^C
open 1
lwp_park 2
times 4
fcntl 5
close 6
sigaction 6
read 10
ioctl 14
sigprocmask 106
write 1092
|
Aus diesem Bericht geht der häufigste Systemaufruf hervor. Das ist in diesem Fall der write(2)-Systemaufruf. Mithilfe des Providers syscall lässt sich nun der Ursprung all dieser write()-Systemaufrufe ergründen:
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(arg2); }'
dtrace: description 'syscall::write:entry' matched 1 probe
^C
value ------------- Distribution ------------- count
0 | 0
1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1037
2 |@ 3
4 | 0
8 | 0
16 | 0
32 |@ 3
64 | 0
128 | 0
256 | 0
512 | 0
1024 |@ 5
2048 | 0
|
Die Ausgabe zeigt, dass der Prozess viele write()-Systemaufrufe mit relativ geringen Datenmengen ausführt. Dieses Verhältnis könnte die Ursache des Leistungsproblems für diesen bestimmten Prozess darstellen. Dies ist ein Beispiel für eine allgemeine Methode zur Erkundung des Systemaufrufverhaltens.
Die Aktion ustack()
Die Ablaufverfolgung des Stacks eines Prozess-Threads zum Zeitpunkt der Aktivierung eines bestimmten Prüfpunkts gibt häufig sehr gründlich Aufschluss über ein Problem. Die Aktion ustack() dient zur Ablaufverfolgung des Stacks eines Benutzer-Threads. Wenn beispielsweise ein Prozess, der zahlreiche Dateien öffnet, gelegentlich beim open(2)-Systemaufruf scheitert, können Sie mit der Aktion ustack() den Codepfad ermitteln, der den fehlgeschlagenen open() ausführt:
syscall::open:entry
/pid == $1/
{
self->path = copyinstr(arg0);
}
syscall::open:return
/self->path != NULL && arg1 == -1/
{
printf("open for '%s' failed", self->path);
ustack();
}
Dieses Skript veranschaulicht auch die Verwendung der Makrovariable $1, die den Wert des ersten in der dtrace(1M)-Befehlszeile angegebenen Operanden annimmt:
# dtrace -s ./badopen.d 31337
dtrace: script './badopen.d' matched 2 probes
CPU ID FUNCTION:NAME
0 40 open:return open for '/usr/lib/foo' failed
libc.so.1`__open+0x4
libc.so.1`open+0x6c
420b0
tcsh`dosource+0xe0
tcsh`execute+0x978
tcsh`execute+0xba0
tcsh`process+0x50c
tcsh`main+0x1d54
tcsh`_start+0xdc
|
Die Aktion ustack() zeichnet Programmzählerwerte (PC) für den Stack auf und dtrace(1M) löst diese PC-Werte anhand der Symboltabellen des Prozesses in Symbolnamen auf. Kann dtrace einen PC-Wert nicht in ein Symbol auflösen, wird der Wert als Hexadezimalzahl ausgegeben.
Wenn ein Prozess bereits vor der Formatierung der ustack()-Daten für die Ausgabe vorhanden ist oder mit kill abgebrochen wird, kann dtrace die PC-Werte im Stack-Protokoll unter Umständen nicht in Symbolnamen umwandeln und ist gezwungen, sie als Hexadezimalzahlen anzuzeigen. Um diese Einschränkung zu umgehen, übergeben Sie -dtrace mit der Option -c oder p gezielt einen Prozess. Ausführliche Informationen zu diesen und anderen Optionen finden Sie in Kapitel 14Das Dienstprogramm dtrace(1M). Sind Prozess-ID oder Befehl im Voraus nicht bekannt, lässt sich die Einschränkung auch mit folgendem D-Programm umgehen:
/*
* This example uses the open(2) system call probe, but this technique
* is applicable to any script using the ustack() action where the stack
* being traced is in a process that may exit soon.
*/
syscall::open:entry
{
ustack();
stop_pids[pid] = 1;
}
syscall::rexit:entry
/stop_pids[pid] != 0/
{
printf("stopping pid %d", pid);
stop();
stop_pids[pid] = 0;
}
Das obige Skript hält einen Prozess kurz vor dessen Beendigung an, wenn die Aktion ustack() auf einen Thread in diesem Prozess angewendet wurde. Diese Technik gewährleistet, dass der Befehl dtrace in der Lage ist, die PC-Werte in symbolische Namen aufzulösen. Beachten Sie, dass der Wert von stop_pids[pid], nachdem er zum Löschen der dynamischen Variable benutzt wurde, 0 beträgt. Denken Sie daran, angehaltene Prozesse mit dem Befehl prun(1) wieder zum Laufen zu bringen. Anderenfalls sammeln sich auf dem System zahlreiche angehaltene Prozesse an.
Der Vektor uregs[]
Der Vektor uregs[] ermöglicht den Zugriff auf einzelne Benutzerregister. Die folgenden Tabellen enthalten die Indizes im Vektor uregs[] für jede unterstützte Solaris-Systemarchitektur.
Tabelle 33–1 uregs[]-Konstanten für SPARC|
Konstante |
Register |
|---|---|
|
R_G0..R_G7 |
%g0....%g7 globale Register |
|
R_O0..R_O7 |
%o0....%o7 Ausgangsregister |
|
R_L0..R_L7 |
%l0....%l7 lokale Register |
|
R_I0..R_I7 |
%i0....%i7 Eingangsregister |
|
R_CCR |
%ccr Bedingungscode-Register |
|
R_PC |
%pc Programmzähler |
|
R_NPC |
%npc nächster Programmzähler |
|
R_Y |
%y Multiplikations-/Divisionsregister |
|
R_ASI |
%asi Adressraum-ID-Register |
|
R_FPRS |
%fprs Status der Gleitkommaregister |
Tabelle 33–2 uregs[]-Konstanten für x86
|
Konstante |
Register |
|---|---|
|
R_CS |
%cs |
|
R_GS |
%gs |
|
R_ES |
%es |
|
R_DS |
%ds |
|
R_EDI |
%edi |
|
R_ESI |
%esi |
|
R_EBP |
%ebp |
|
R_EAX |
%eax |
|
R_ESP |
%esp |
|
R_EAX |
%eax |
|
R_EBX |
%ebx |
|
R_ECX |
%ecx |
|
R_EDX |
%edx |
|
R_TRAPNO |
%trapno |
|
R_ERR |
%err |
|
R_EIP |
%eip |
|
R_CS |
%cs |
|
R_ERR |
%err |
|
R_EFL |
%efl |
|
R_UESP |
%uesp |
|
R_SS |
%ss |
Auf AMD64-Plattformen hat der Vektor uregs denselben Inhalt wie auf x86-Plattformen und zusätzlich die in der folgenden Tabelle aufgeführten Elemente:
Tabelle 33–3 uregs[]-Konstanten für amd64|
Konstante |
Register |
|---|---|
|
R_RSP |
%rsp |
|
R_RFL |
%rfl |
|
R_RIP |
%rip |
|
R_RAX |
%rax |
|
R_RCX |
%rcx |
|
R_RDX |
%rdx |
|
R_RBX |
%rbx |
|
R_RBP |
%rbp |
|
R_RSI |
%rsi |
|
R_RDI |
%rdi |
|
R_R8 |
%r8 |
|
R_R9 |
%r9 |
|
R_R10 |
%r10 |
|
R_R11 |
%r11 |
|
R_R12 |
%r12 |
|
R_R13 |
%r13 |
|
R_R14 |
%r14 |
|
R_R15 |
%r15 |
Die Aliasnamen in der folgenden Tabelle können auf allen Plattformen verwendet werden:
Tabelle 33–4 Gemeinsame uregs[]-Konstanten|
Konstante |
Register |
|---|---|
|
R_PC |
Programmzähler-Register |
|
R_SP |
Stack-Zeiger-Register |
|
R_R0 |
erster Rückgabecode |
|
R_R1 |
zweiter Rückgabecode |
Der Provider pid
Der Provider pid ermöglicht die Ablaufverfolgung beliebiger Anweisungen in einem Prozess. Anders als mit den meisten anderen Providern, werden pid-Prüfpunkte nach Bedarf und gemäß den in den D-Programmen enthaltenen Prüfpunktbeschreibungen erzeugt. Deshalb sind in der Ausgabe von dtrace -l keine pid-Prüfpunkte aufgeführt, die Sie nicht selbst aktivieren.
Ablaufverfolgung von Benutzerfunktionsgrenzen
Am einfachsten kann der Provider pid als Gegenstück des Providers fbt für den Benutzerraum eingesetzt werden. Das folgende Beispielprogramm verfolgt jeden Eintritt in eine und Rückkehr aus einer einzigen Funktion. Die Makrovariable $1 (erster Operand in der Befehlszeile) ist die Prozess-ID des zu überwachenden Prozesses. Die Makrovariable $2 (zweiter Operand in der Befehlszeile) ist der Name der Funktion, aus der alle Funktionsaufrufe verfolgt werden sollen.
Beispiel 33–1 userfunc.d: Ablaufverfolgung von Eintritt in und Rückkehr aus einer Benutzerfunktion
pid$1::$2:entry
{
self->trace = 1;
}
pid$1::$2:return
/self->trace/
{
self->trace = 0;
}
pid$1:::entry,
pid$1:::return
/self->trace/
{
}
Geben Sie das obige Beispielskript ein und speichern Sie es in einer Datei namens userfunc.d. Machen Sie es dann mit chmod ausführbar. Das Skript produziert eine Ausgabe wie im folgenden Beispiel:
# ./userfunc.d 15032 execute dtrace: script './userfunc.d' matched 11594 probes 0 -> execute 0 -> execute 0 -> Dfix 0 <- Dfix 0 -> s_strsave 0 -> malloc 0 <- malloc 0 <- s_strsave 0 -> set 0 -> malloc 0 <- malloc 0 <- set 0 -> set1 0 -> tglob 0 <- tglob 0 <- set1 0 -> setq 0 -> s_strcmp 0 <- s_strcmp ... |
Der Provider pid kann nur auf bereits laufende Prozesse angewendet werden. Mit der Makrovariable $target (siehe Kapitel 15Scripting) und den dtrace-Optionen -c und -p lassen sich gewünschte Prozesse erzeugen und fassen (grab) und mit DTrace instrumentieren. Mit dem folgenden D-Skript können Sie beispielsweise die Verteilung der von einem bestimmten Subjektprozess ausgeführten libc-Aufrufe ermitteln:
pid$target:libc.so::entry
{
@[probefunc] = count();
}
Um die Verteilung derartiger vom Befehl date(1) ausgeführter Aufrufe zu ermitteln, speichern Sie das Skript in der Datei libc.d und führen folgenden Befehl aus:
# dtrace -s libc.d -c date dtrace: script 'libc.d' matched 2476 probes Fri Jul 30 14:08:54 PDT 2004 dtrace: pid 109196 has exited pthread_rwlock_unlock 1 _fflush_u 1 rwlock_lock 1 rw_write_held 1 strftime 1 _close 1 _read 1 __open 1 _open 1 strstr 1 load_zoneinfo 1 ... _ti_bind_guard 47 _ti_bind_clear 94 |
Ablaufverfolgung beliebiger Anweisungen
Mit dem Provider pid können beliebige Anweisungen in beliebigen Benutzerfunktionen verfolgt werden. Dazu erzeugt der Provider pid nach Bedarf für jede Anweisung in einer Funktion einen Prüfpunkt. Der Name jedes Prüfpunkt entspricht dem Versatz der entsprechenden Anweisung in der Funktion, ausgedrückt durch eine Hexadezimalzahl. Um beispielsweise einen Prüfpunkt für die Anweisung an Versatz 0x1c in der Funktion foo des Moduls bar.so des Prozesses mit der PID 123 zu aktivieren, könnten Sie den folgenden Befehl eingeben:
# dtrace -n pid123:bar.so:foo:1c |
Wenn Sie alle Prüfpunkte in der Funktion foo, einschließlich des Prüfpunkts für jede Anweisung, aktivieren möchten, können Sie den folgenden Befehl verwenden:
# dtrace -n pid123:bar.so:foo: |
Dieser Befehl stellt eine äußerst leistungsfähige Technik zum Debuggen und Analysieren von Benutzeranwendungen dar. Seltene Fehler sind mitunter nicht leicht zu erkennen und zu beheben, da sie sich nur schwer reproduzieren lassen. Häufig kann ein Problem erst nach dem Auftreten einer Störung identifiziert werden - zu spät, um den Codepfad zu rekonstruieren. Das folgende Beispiel zeigt, wie sich durch Kombination des Providers pid mit spekulativer Ablaufverfolgung (siehe Kapitel 13Spekulative Ablaufverfolgung) jede Anweisung in einer Funktion verfolgen und das Problem somit lösen lässt.
Beispiel 33–2 errorpath.d: Ablaufverfolgung des Pfads bei Fehler in Benutzerfunktionsaufruf
pid$1::$2:entry
{
self->spec = speculation();
speculate(self->spec);
printf("%x %x %x %x %x", arg0, arg1, arg2, arg3, arg4);
}
pid$1::$2:
/self->spec/
{
speculate(self->spec);
}
pid$1::$2:return
/self->spec && arg1 == 0/
{
discard(self->spec);
self->spec = 0;
}
pid$1::$2:return
/self->spec && arg1 != 0/
{
commit(self->spec);
self->spec = 0;
}
Die Ausführung von errorpath.d erzeugt eine Ausgabe wie in folgendem Beispiel:
# ./errorpath.d 100461 _chdir dtrace: script './errorpath.d' matched 19 probes CPU ID FUNCTION:NAME 0 25253 _chdir:entry 81e08 6d140 ffbfcb20 656c73 0 0 25253 _chdir:entry 0 25269 _chdir:0 0 25270 _chdir:4 0 25271 _chdir:8 0 25272 _chdir:c 0 25273 _chdir:10 0 25274 _chdir:14 0 25275 _chdir:18 0 25276 _chdir:1c 0 25277 _chdir:20 0 25278 _chdir:24 0 25279 _chdir:28 0 25280 _chdir:2c 0 25268 _chdir:return |
- © 2010, Oracle Corporation and/or its affiliates