Hey,
jeder Softwareentwickler oder Systemadministrator kennt das Problem. Ein Prozess läuft tierisch lange, stürzt ab, frisst viel CPU oder hängt einfach nur fest.
Jetzt kann man natürlich anfangen und seinen Code mit Logaufrufen verminen, das führt oft zum Ziel, kann aber sehr aufwändig werden.
Für einen ersten Überblick eignet sich das Tool "strace" sehr gut.
Die meisten von euch werden es sicherlich schon kennen, trotzdem möchte ich euch heute ein paar nützliche Anwendungsbeispiele zeigen.
1. Ausgabeumleitung
Da strace standardmäßig auf stderr und nicht stdout schreibt, muss die Umleitung so erfolgen:
"strace ls -al &> strace.log"
alternativ mit der Option "-o" in eine Datei schreiben
"strace -o strace.log ls -al"
2. Uhrzeit vor jeden Aufruf
root@pc:~/testdir#strace -t echo "test"
18:36:03 execve("/bin/echo", ["echo", "test"], [/* 18 vars */]) = 0
18:36:03 brk(0) = 0xe0f000
18:36:03 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
18:36:03 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff95a938000
18:36:03 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
18:36:03 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
18:36:03 fstat(3, {st_mode=S_IFREG|0644, st_size=32701, ...}) = 0
18:36:03 mmap(NULL, 32701, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff95a930000
18:36:03 close(3) = 0
18:36:03 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
18:36:03 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
18:36:03 read(3, "\177ELF\2\1\1\3>\1\200\30\2"..., 832) = 832
18:36:03 fstat(3, {st_mode=S_IFREG|0755, st_size=1811128, ...}) = 0
18:36:03 mmap(NULL, 3925208, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7ff95a359000
18:36:03 mprotect(0x7ff95a50e000, 2093056, PROT_NONE) = 0
18:36:03 mmap(0x7ff95a70d000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b4000) = 0x7ff95a70d000
18:36:03 mmap(0x7ff95a713000, 17624, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7ff95a713000
18:36:03 close(3) = 0
18:36:03 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff95a92f000
18:36:03 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff95a92e000
18:36:03 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff95a92d000
18:36:03 arch_prctl(ARCH_SET_FS, 0x7ff95a92e700) = 0
18:36:03 mprotect(0x7ff95a70d000, 16384, PROT_READ) = 0
18:36:03 mprotect(0x605000, 4096, PROT_READ) = 0
18:36:03 mprotect(0x7ff95a93a000, 4096, PROT_READ) = 0
18:36:03 munmap(0x7ff95a930000, 32701) = 0
18:36:03 brk(0) = 0xe0f000
18:36:03 brk(0xe30000) = 0xe30000
18:36:03 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
18:36:03 fstat(3, {st_mode=S_IFREG|0644, st_size=1607664, ...}) = 0
18:36:03 mmap(NULL, 1607664, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7ff95a7a4000
18:36:03 close(3) = 0
18:36:03 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 0), ...}) = 0
18:36:03 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff95a937000
18:36:03 write(1, "test\n", 5test
) = 5
18:36:03 close(1) = 0
18:36:03 munmap(0x7ff95a937000, 4096) = 0
18:36:03 close(2) = 0
18:36:03 exit_group(0)3. Wie lange braucht jeder Aufruf?
root@pc:~/testdir#strace -r echo "test"
0.000000 execve("/bin/echo", ["echo", "test"], [/* 18 vars */]) = 0
0.000619 brk(0) = 0x1f3d000
0.000151 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000146 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f89a4100000
0.000123 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
0.000123 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
0.000093 fstat(3, {st_mode=S_IFREG|0644, st_size=32701, ...}) = 0
0.000144 mmap(NULL, 32701, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f89a40f8000
0.000090 close(3) = 0
0.000096 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
0.000115 open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
0.000103 read(3, "\177ELF\2\1\1\3>\1\200\30\2"..., 832) = 832
0.000121 fstat(3, {st_mode=S_IFREG|0755, st_size=1811128, ...}) = 0
0.000135 mmap(NULL, 3925208, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f89a3b21000
0.000092 mprotect(0x7f89a3cd6000, 2093056, PROT_NONE) = 0
0.000100 mmap(0x7f89a3ed5000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b4000) = 0x7f89a3ed5000
0.000108 mmap(0x7f89a3edb000, 17624, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f89a3edb000
0.000107 close(3) = 0
0.000126 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f89a40f7000
0.000098 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f89a40f6000
0.000101 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f89a40f5000
0.000101 arch_prctl(ARCH_SET_FS, 0x7f89a40f6700) = 0
0.000259 mprotect(0x7f89a3ed5000, 16384, PROT_READ) = 0
0.000095 mprotect(0x605000, 4096, PROT_READ) = 0
0.000097 mprotect(0x7f89a4102000, 4096, PROT_READ) = 0
0.000103 munmap(0x7f89a40f8000, 32701) = 0
0.000257 brk(0) = 0x1f3d000
0.000082 brk(0x1f5e000) = 0x1f5e000
0.000128 open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
0.000100 fstat(3, {st_mode=S_IFREG|0644, st_size=1607664, ...}) = 0
0.000136 mmap(NULL, 1607664, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f89a3f6c000
0.000095 close(3) = 0
0.000166 fstat(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(136, 0), ...}) = 0
0.000126 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f89a40ff000
0.000104 write(1, "test\n", 5test
) = 5
0.000110 close(1) = 0
0.000085 munmap(0x7f89a40ff000, 4096) = 0
0.000096 close(2) = 0
0.000103 exit_group(0) = ?Die beiden oben genannten Beispiele können bei umfangreicheren Programmen natürlich sehr schnell sehr unübersichtlich werden. In diesem Fall kann man mit dem folgenden Statement sehr gut herausfinden, welche Calls wie oft gemacht werden, und wie lange sie insgesamt brauchen:
root@pc:~/testdir#strace -c ls -al total 12 drwxr-xr-x 3 root root 4096 Dec 1 18:34 . drwx------ 7 root root 4096 Dec 1 18:34 .. drwxr-xr-x 2 root root 4096 Dec 1 18:34 testfile % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000029 1 37 24 open 0.00 0.000000 0 13 read 0.00 0.000000 0 4 write 0.00 0.000000 0 20 close 0.00 0.000000 0 2 stat 0.00 0.000000 0 15 fstat 0.00 0.000000 0 3 lstat 0.00 0.000000 0 2 poll 0.00 0.000000 0 1 lseek 0.00 0.000000 0 31 mmap 0.00 0.000000 0 16 mprotect 0.00 0.000000 0 5 munmap 0.00 0.000000 0 3 brk 0.00 0.000000 0 2 rt_sigaction 0.00 0.000000 0 1 rt_sigprocmask 0.00 0.000000 0 2 ioctl 0.00 0.000000 0 9 9 access 0.00 0.000000 0 2 socket 0.00 0.000000 0 2 connect 0.00 0.000000 0 2 sendto 0.00 0.000000 0 2 recvmsg 0.00 0.000000 0 1 execve 0.00 0.000000 0 2 getdents 0.00 0.000000 0 1 getrlimit 0.00 0.000000 0 1 statfs 0.00 0.000000 0 1 arch_prctl 0.00 0.000000 0 9 9 lgetxattr 0.00 0.000000 0 2 1 futex 0.00 0.000000 0 1 set_tid_address 0.00 0.000000 0 1 clock_gettime 0.00 0.000000 0 1 openat 0.00 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000029 195 43 total
Natürlich ist strace noch viel mächtiger, sämtliche Parameter und Optionen findet ihr natürlich in der strace Manpage. Die oben genannten Beispiele sollte man sich aber auf jeden Fall notieren, mit Ihnen kommt man in den meisten Fällen schon ein großes Stück weiter.