Debugging durch Beobachten

Manchmal können kleinere Probleme im Gerätetreiber durch die Beobachtung einer Anwendung im User-Space eingekreist werden. Diese Beobachtung kann auch dabei helfen sich davon zu überzeugen, daß der Treiber korrekt arbeitet. Beispielsweise waren wir von scull überzeugt, nachdem wir uns angeschaut hatten, wie die read-Implementation auf read-Anforderungen mit verschiedenen Datenmengen reagierte.

Es gibt verschiedene Möglichkeiten, ein User-Space-Programm zu beobachten. Sie können es im Debugger starten und die Funktionen schrittweise durchlaufen, Ausgabeanweisungen hinzufügen oder das Programm unter strace laufen lassen. Hier besprechen wir nur diese letzte Technik, die besonders interessant ist, wenn das eigentliche Ziel die Untersuchung von Kernel-Code ist.

Der Befehl strace ist ein mächtiges Werkzeug, das alle Systemaufrufe anzeigt, die von einem User-Space-Programm ausgeführt werden. Dabei werden nicht die Aufrufe allein, sondern auch die Argumente und die Rückgabewerte in symbolischer Form angezeigt. Wenn ein Systemaufruf fehlschlägt, wird sowohl der symbolische Wert des Fehlers (z. B. ENOMEM) als auch der zugehörige String (Out of memory) angezeigt. strace hat viele Kommandozeilenoptionen, von denen die wichtigsten folgende sind: –t, um die Zeit anzuzeigen, zu der ein Systemaufruf ausgeführt wird, –T, um die Zeit anzuzeigen, die im Systemaufruf verbraucht wurde, –e, um die verfolgten Aufrufe einzugrenzen, und –o, um die Ausgabe in eine Datei umzuleiten. Per Default gibt strace die Informationen auf stderr aus.

strace bekommt die Informationen aus dem Kernel. Das bedeutet, daß ein Programm mit strace unabhängig davon beobachtet werden kann, ob es mit Debugging-Unterstützung (der –g-Option des gcc) übersetzt wurde oder nicht oder vielleicht sogar gestrippt worden ist. Außerdem können Sie strace auf einen bereits laufenden Prozeß ansetzen, ähnlich wie sich auch ein Debugger mit einem laufenden Prozeß verbinden und diesen kontrollieren kann.

Die Informationen von strace werden oft verwendet, um Fehlerberichte an Applikationsprogrammierer zu schicken. Aber strace ist auch sehr wertvoll für Kernel-Programmierer. Wir haben schon gesehen, wie Treiber-Code durch die Ausführung von Systemaufrufen ausgeführt wird, und mit strace können wir die Konsistenz der Eingabe- und Ausgabedaten jedes Aufrufs überprüfen.

Ein Beispiel: Die folgende Ausgabe zeigt die letzten Zeilen eines strace-Protokolls mit strace ls /dev > /dev/scull0:



[...]
open("/dev", O_RDONLY|O_NONBLOCK)     = 4
fcntl(4, F_SETFD, FD_CLOEXEC)         = 0
brk(0x8055000)                        = 0x8055000
lseek(4, 0, SEEK_CUR)                 = 0
getdents(4, /* 70 entries */, 3933)   = 1260
[...]
getdents(4, /* 0 entries */, 3933)    = 0
close(4)                              = 0
fstat(1, {st_mode=S_IFCHR|0664, st_rdev=makedev(253, 0), ...}) = 0
ioctl(1, TCGETS, 0xbffffa5c)          = -1 ENOTTY (Inappropriate ioctl
                                                     for device)
write(1, "MAKEDEV\natibm\naudio\naudio1\na"..., 4096) = 4000
write(1, "d2\nsdd3\nsdd4\nsdd5\nsdd6\nsdd7"..., 96) = 96
write(1, "4\nsde5\nsde6\nsde7\nsde8\nsde9\n"..., 3325) = 3325
close(1)                              = 0
_exit(0)                              = ?

Offensichtlich hat der erste write-Systemaufruf, nachdem ls das Zielverzeichnis fertig gelesen hat, versucht, 4 KByte zu schreiben. Merkwürdigerweise (aus Sicht von ls) wurden jedoch nur viertausend Bytes geschrieben und die Operation erneut gestartet. Wir wissen jedoch, daß die Implementation von write in scull nur ein Quantum zur gleichen Zeit schreibt, so daß wir mit dem partiellen Schreiben hätten rechnen können. Nach einigen Schritten läuft dann aber alles durch, und das Programm beendet sich erfolgreich.

Lassen wir jetzt als weiteres Beispiel read vom scull-Gerät lesen (mit dem Befehl wc):



[...]
open("/dev/scull0", O_RDONLY)           = 4
fstat(4, {st_mode=S_IFCHR|0664, st_rdev=makedev(253, 0), ...}) = 0
read(4, "MAKEDEV\natibm\naudio\naudio1\na"..., 16384) = 4000
read(4, "d2\nsdd3\nsdd4\nsdd5\nsdd6\nsdd7"..., 16384) = 3421
read(4, "", 16384)                      = 0
fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(3, 7), ...}) = 0
ioctl(1, TCGETS, {B38400 opost isig icanon echo ...}) = 0
write(1, "   7421 /dev/scull0\n", 20)   = 20
close(4)                                = 0
_exit(0)                                = ?

Wie erwartet, kann read nur viertausend Bytes zur gleichen Zeit lesen, aber die totale Datenmenge ist die gleiche wie im vorigen Beispiel. Es ist interessant zu sehen, wie die zusätzlichen Versuche in diesem Beispiel im Gegensatz zum letzten angeordnet sind. wc ist dafür optimiert, möglichst schnell zu lesen, umgeht deshalb die Standardbibliothek und versucht, in einem Systemaufruf mehr Daten zu lesen. Sie können an den read-Zeilen im Protokoll sehen, daß wc versucht hat, 16 KByte pro Aufruf zu lesen.

Linux-Experten finden in der Ausgabe von strace noch mehr nützliche Informationen. Wenn die ganzen Symbole Sie abschrecken, dann können Sie sich auch darauf beschränken zu beobachten, wie die Dateimethoden (open, read usw.) arbeiten.

Wir persönlich finden strace besonders nützlich, um Laufzeitfehler in Systemaufrufen zu entdecken. Oft ist ein Aufruf von perror in Applikationen oder Demo-Programmen nicht ausführlich genug, um zum Debuggen nützlich zu sein. Es kann eine große Hilfe sein, wenn man genau sagen kann, welche Argumente in welchem Systemaufruf einen Fehler ausgelöst haben.