strace
- Urspruenglicher Autor: Ramon Kukla
- Urspruengliches Datum: 16.09.2011
Ist schon wieder Freitag? Ja tatsaechlich, ist es. Also los…
Es gibt ja verschiedene Wege mit Problemen umzugehen. Hat man bei Problemen entsprechende Logs oder Rueckmeldungen, kann man damit beispielsweise die Suchmaschine seiner Wahl bemuehen. Oder die Meldung ist schon so eindeutig, dass man gleich weiss wo man dran ist.
Es passiert aber auch immer wieder, dass ein Tool nicht tut was man erwartet, man aber auch keine Rueckmeldung bekommt. Fuer mich ist das oft der Punkt an dem ich aus einer von zwei Moeglichkeiten waehle. Ist das Tool neu und nicht wichtig genug, fliegt es wieder vom Rechner. Nutze ich das Tool aber schon laenger, oder ist es wichtig, bzw. gibt es keine sinnvolle Alternative, nehme ich gerne strace zur Hand.
Die man-Page von strace sagt, dass man „system calls und signals“ verfolgen kann. Und das trifft es auch ganz gut soweit. So kann man beispielsweise einfach mal ein strace whoami absetzen und schauen was (gekuerzt) raus kommt.
execve("/usr/bin/whoami", ["whoami"], [/* 47 vars */]) = 0
brk(0) = 0x9707000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb781e000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=64435, ...}) = 0
mmap2(NULL, 64435, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb780e000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\220o\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1434180, ...}) = 0
mmap2(NULL, 1444360, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x110000
mprotect(0x26a000, 4096, PROT_NONE) = 0
mmap2(0x26b000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15a) = 0x26b000
mmap2(0x26e000, 10760, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x26e000
...
write(1, "ramon\n", 6ramon
) = 6
close(1) = 0
munmap(0xb781c000, 4096) = 0
close(2) = 0
exit_group(0) = ?
Die Ausgabe von strace ist auch schon im Standard relativ umfangreich. Wobei man sich nicht von der schieren Menge erschrecken lassen sollte. Man wird viele Eintraege sehen, die beinahe selbst erklaerend sind. Ein Teil „open“, „close“, „read“ oder „exit“. Natuerlich hat man auch Eintraege, die nicht auf den ersten Blick klar sind. Da hilft dann ein dezener Blick in „syscalls - Linux system calls“ auf kernel.org (was hoffentlich bald mal wieder erreichbar ist).
Ein haeufiger Fehler ist, dass eine Datei nicht gefunden oder geoeffnet (z.B. Berechtigung) werden kann. Wird eine Datei nicht gefunden kann das in einem strace etwa wie folgt ausschauen.
open("/lib/libgcrypt.so.11", O_RDONLY) = -1 ENOENT (No such file or directory)
Hier wird die Datei libgcrypt.so.11 nicht gefunden. Fairerweise muss gesagt werden, dass es nicht immer reicht den Fehler zu kennen. Denn… Ich sehe zwar, dass die Datei nicht gefunden wird, muss mich aber zumindest noch schlau machen wie ich diese nun auf mein System bekomme. Ist aber ein anderes Thema.
strace hat, wie so viele tolle Kommandos, umfangreiche Optionen. Eine sehr interessante Option, die einem schon mal zeigt was auf einen zukommt, ist -c.
ramon@bullfrog ~ $ strace -c whoami ramon % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- -nan 0.000000 0 9 read -nan 0.000000 0 1 write -nan 0.000000 0 38 13 open -nan 0.000000 0 29 close -nan 0.000000 0 1 execve -nan 0.000000 0 7 7 access -nan 0.000000 0 3 brk -nan 0.000000 0 7 munmap -nan 0.000000 0 8 mprotect -nan 0.000000 0 2 _llseek -nan 0.000000 0 34 mmap2 -nan 0.000000 0 26 fstat64 -nan 0.000000 0 1 geteuid32 -nan 0.000000 0 1 fcntl64 -nan 0.000000 0 1 set_thread_area -nan 0.000000 0 2 socket -nan 0.000000 0 2 2 connect ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 172 22 total
Auch interessant, wenn es *noch* tiefer gehen soll, ist die Option -f. Hierbei wird dann auch den Kinderprozessen gefolgt. Hier mal, gekuerzt, was strace -c sh -c 'for i in $(cat dupes_*); do echo $i; done ausgibt…
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 84.22 0.004093 0 83870 write 15.25 0.000741 0 26798 read 0.53 0.000026 26 1 wait4 ... 0.00 0.000000 0 1 set_thread_area ------ ----------- ----------- --------- --------- ---------------- 100.00 0.004860 110717 3 total
…und nachfolgend
strace -f -c sh -c 'for i in $(cat dupes_*); do echo $i; done
(also mit Kinderprozessen).
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 85.34 0.007601 0 83980 write 14.35 0.001278 0 26923 read 0.31 0.000028 28 1 wait4 ... 0.00 0.000000 0 2 set_thread_area ------ ----------- ----------- --------- --------- ---------------- 100.00 0.008907 111103 24 total
Man sieht, mit strace kann man viel Spass haben. Aber neben dem Spass hilft es in der Tat durchaus Problemen auf den Grund zu gehen. Man kann strace uebrigens auch an laufende Prozesse anhaengen. Allerdings habe ich schon mal gesehen, dass beim Beenden von strace auch der Prozess abgeschmiert ist. Das ist, meine ich, nicht normal, sollte man aber im Hinterkopf behalten. Vor allem wenn man ein Prozess auf einem produktiven Server mit 500 Benutzern untersuchen will.