Berny's Knowledgebase als Newsfeed

Was treibt dieses Programm eigentlich so?

Wenn man genauer wissen will, was ein Programm tut, z. B. welche Dateien es öffnet, bzw. wo es nach Dateien sucht, … dann liest man den Quellcode. Wenn das in der aktuellen Situation - z. B. Problemanalyse - zu aufwändig oder nicht möglich ist, kommt meist als nächstes auf den einschlägigen Mailinglisten der Hardcore-Linux-User der Hinweis, man möge doch strace verwenden. Ein echt nützliches Tool, das hier mal kurz vorgestellt werden soll.

Man stellt dabei normalerweise den Aufruf von strace einfach dem zu untersuchenden Programmaufruf voran:

strace -o log.txt <command>

Alle System-Calls, die <command> so verwendet, werden dabei in die angegebene Log-Datei geschrieben. Standardmäßig wird dabei ein recht übersichtliches Format gewählt. Bei Returncodes wird z. B. deren Bedeutung im Klartext angehängt, z. B.

open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)

Ausserdem werden längliche Ausgaben auf die wichtigsten Infos gekürzt, und über drei Punkte angedeutet, dass es noch mehr Infos gäbe:

fstat64(3, {st_mode=S_IFREG|0644, st_size=2570, ...}) = 0

Wer die übrigen Infos braucht, ruft strace mit dem zusätzlichen Schalten -v auf:

strace -v -o log.txt <command>

Dann wird die gleiche Ausgabe länglicher:

fstat64(3, {st_dev=makedev(252, 1), st_ino=7340160, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=2570, st_atime=2010/09/30-22:57:20, st_mtime=2010/03/04-13:28:50, st_ctime=2010/04/30-22:59:13}) = 0

Um sich die Ausgabe-Datei anzuschauen, benutzt man am besten vim, denn der bringt Syntax-Highlighting für dieses Format mit. Damit liest sich der Trace deutlich schneller und komfortabler.

Filter

Wem die Ausgabedatei zu unübersichtlich ist, der kann die Ausgabe auch gleich filtern. Dies ist nützlich, wenn man schon weiß, wonach man sucht. Wenn z. B. die Frage zu klären ist: Ja wo sucht er denn jetzt sein Config-File, dann sind einfach nur bestimmte System-Calls interessant:

strace -e trace=open -o log.txt <command>

verkürzt log.txt dramatisch.

Es sind auch Kombinationen aus mehreren möglich

strace -e trace=open,read,write -o log.txt <command>

Ggf. kann es auch sinnvoll sein, sich zunächst mit -c eine zusammenfassende Statistik erzeugen zu lassen: Welcher System-Call ist wie oft gelaufen und wieviele davon liefen mit Error? Auf die "verdächtigen" kann man dann ja mal filtern…

Was dauert denn da so lange?

Für Laufzeit-Analysen ist der Schalter -tt interessant, er stellt jeder Zeile einen Timestamp (bei den Sekunden mit 5 Nachkommastellen) voran. -t (Genauigkeit 1 sec) ist oft zu ungenau. -ttt dagegen eher unübersichtlich.

Interessanter kann schon wieder -r sein, relative Tiemstamps.

-T hängt hinten an jede Zeile (in spitzen Klammern) eine Information an, wie lange der entsprechende System-Call gelaufen ist.

Sonst noch…

Weiterhin sind folgende Schalter interessant:

-f

auch Kindprozesse tracen

-F

auch Vfork-Kindprozesse tracen

strace nachträglich

Auch das geht: Man hat einen Prozess der scheinbar nichts mehr tut, oder ggf. auch einen, der wie wild Resourcen verbraucht. Dieser war nicht von Anfang an durch strace unter Beobachtung gestellt. Aber kein Problem: Einen strace kann man nachträglich auch noch dran hängen

strace -o log.txt -p <PID>

oder auch

strace -p <PID>

um direkt auf der Konsole mitzulesen. Dabei ist dann aber wohl ein Filter sinnvoll:

strace -e trace=open,read,write -p <PID>

Während strace sich normalerweise automatisch mit beendet, sobald der zu untersuchenden Prozess endet, kann ein nachträglich angehängter strace (der ja auf einer separaten Konsole läuft) dort auch eigenständig beendet werden mit Ctrl-C.