strace는 시스템 콜과 시그널을 추적

strace는 시스템 콜과 시그널을 추적하는 프로그램이며 프로그램의 문제를 분석하고 디버깅하는데 유용하다. 시스템 관리자, 분석가, 트러블 슈터라면 strace를 사용하므로써 프로그램을 재컴파일할 필요가 없기 때문에 프로그램의 소스가 가용하지 않을 때 사용하면 매우 유용할 것이다.
사용 가능한 옵션
strace [ -dffhiqrtttTvxx ] [ -acolumn ] [ -eexpr ] ... [ -ofile ] [-ppid ] ... [ -sstrsize ] [ -uusername ] [ -Evar=val ] ... [ -Evar ] ... [ command [ arg ... ] ] 
strace -c [ -eexpr ] ... [ -Ooverhead ] [ -Ssortby ] [ command [ arg... ] ]
위와 같이 다양한 옵션이 있지만 사용 방법은 크게 프로세스 아이디로 추적하느냐 또는 command로 추적하느냐 두가지이며 여기에 옵션들을 추가해서 출력을 조작할 수 있다.
-c 각각의 시스템 콜에 대한 시간, 콜 개수, 에러를 카운트하고 프로그램 탈출 시 보고된다.
예)
[root@linux root]# strace -c ls
execve("/bin/ls", ["ls"], [/* 24 vars */]) = 0
Desktop bin install.log.syslog nsmail snmp_setup.sh
EGAVGA.BGI bsd_snmp_setup.sh less-378-8KR.src.rpm p_test source
ElectricFence-2.2.2-11.i386.rpm c_test libr.pl p_test_old src
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
47.97 0.007413 674 11 write
15.00 0.002318 211 11 1 open
8.75 0.001352 169 8 read
6.99 0.001080 60 18 old_mmap
5.63 0.000870 87 10 close
3.19 0.000493 123 4 munmap
2.55 0.000394 36 11 fstat64
1.87 0.000289 72 4 2 rt_sigaction
1.84 0.000285 143 2 getdents64
1.75 0.000271 271 1 set_thread_area
1.20 0.000186 47 4 brk
1.06 0.000164 55 3 mmap2
0.66 0.000102 102 1 uname
0.61 0.000095 48 2 ioctl
0.28 0.000044 44 1 fcntl64
0.24 0.000037 37 1 getrlimit
0.22 0.000034 34 1 set_tid_address
0.17 0.000027 27 1 rt_sigprocmask
------ ----------- ----------- --------- --------- ----------------
100.00 0.015454 94 3 total
-f 추적 중인 프로세스가 fork한 자식 프로세스들을 추적한다.
예)
[root@linux root]# strace -f -r -p 11551
Process 11551 attached - interrupt to quit
select(0, NULL, NULL, NULL, {0, 440000}) = 0 (Timeout)
time(NULL) = 1077928680
waitpid(-1, 0xbfe9692c, WNOHANG) = 0
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
time(NULL) = 1077928681
waitpid(-1, 0xbfe9692c, WNOHANG) = 0
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
time(NULL) = 1077928682
waitpid(-1, 0xbfe9692c, WNOHANG) = 0
...
[pid 11551] 0.008273 waitpid(-1, 0xbfe9692c, WNOHANG) = 0
[pid 11551] 0.002466 select(0, NULL, NULL, NULL, {1, 0}<unfinished ...>
[pid 14442] 0.004551 --- SIGSTOP (Stopped (signal)) @ 0 (0) ---
...
[pid 11551] 0.004858 time(NULL) = 1077928738
[pid 11551] 0.002505 waitpid(-1, 0xbfe9692c, WNOHANG) = 0
[pid 11551] 0.003191 select(0, NULL, NULL, NULL, {1, 0}<unfinished ...>
Process 11551 detached
Process 14442 detached
[pid 14442]처럼 [] 안에 프로세스 아이디가 부모 프로세스와 자식 프로세스의 아이디를 보여주면서 자식 프로세스까지 추적하고 있다.
-r 각 시스템 콜에 대한 엔트리 상의 관련 타임스탬프를 출력한다. 이는 성공한 시스템 콜들이 시작된 시간 사이의 시간차를 기록한다.
예)
[root@linux root]# strace -r ls
0.000000 execve("/bin/ls", ["ls"], [/* 24 vars */]) = 0
0.002387 uname({sys="Linux", node="linux.braineyes.com", ...}) = 0
0.006998 brk(0) = 0x849f000
0.002207 open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
0.004006 open("/etc/ld.so.cache", O_RDONLY) = 3
0.004462 fstat64(3, {st_mode=S_IFREG|0644, st_size=55211, ...}) = 0
0.002907 old_mmap(NULL, 55211, PROT_READ, MAP_PRIVATE, 3, 0) = 0xbf5d8000
0.002233 close(3) = 0
0.004835 open("/lib/tls/librt.so.1", O_RDONLY) = 3
-t 각 라인에 시간을 출력한다.
예)
[root@linux root]# strace -t -p 14460
Process 14460 attached - interrupt to quit
09:50:04 select(0, NULL, NULL, NULL, {0, 380000}) = 0 (Timeout)
09:50:04 time(NULL) = 1077929404
09:50:04 waitpid(-1, 0xbfeb66bc, WNOHANG) = 0
09:50:04 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
09:50:05 time(NULL) = 1077929405
09:50:05 waitpid(-1, 0xbfeb66bc, WNOHANG) = 0
09:50:05 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
09:50:06 time(NULL) = 1077929406
09:50:06 waitpid(-1, 0xbfeb66bc, WNOHANG) = 0
09:50:06 select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)
09:50:07 time(NULL) = 1077929407
09:50:10 select(0, NULL, NULL, NULL, {1, 0}<unfinished ...>
-T 시스템 콜에 소요된 시간을 출력한다.
예)
[root@linux root]# strace -T -p 14460
Process 14460 attached - interrupt to quit
select(0, NULL, NULL, NULL, {0, 480000}) = 0 (Timeout)<0.475699>
time(NULL) = 1077929488<0.000835>
waitpid(-1, 0xbfeb66bc, WNOHANG) = 0<0.001862>
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)<0.998481>
time(NULL) = 1077929489<0.000717>
waitpid(-1, 0xbfeb66bc, WNOHANG) = 0<0.000616>
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)<0.998707>
time(NULL) = 1077929490<0.000819>
select(5, NULL, [4], NULL, {0, 0}) = 1 (out [4], left {0, 0})<0.000875>
waitpid(-1, 0xbfeb66bc, WNOHANG) = 0<0.000717>
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)<0.995155>
time(NULL) = 1077929491<0.000875>
waitpid(-1, 0xbfeb66bc, WNOHANG) = 0<0.002018>
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)<0.998356>
time(NULL) = 1077929492<0.000713>
waitpid(-1, 0xbfeb66bc, WNOHANG) = 0<0.000604>
select(0, NULL, NULL, NULL, {1, 0}) = 0 (Timeout)<0.999052>
time(NULL) = 1077929493<0.001457>
waitpid(-1, 0xbfeb66bc, WNOHANG) = 0<0.000825>
select(0, NULL, NULL, NULL, {1, 0}<unfinished ...>
Process 14460 detached
-e expr 추적할 이벤트가 어떤 것인지 그것을 어떻게 추적할 것인지를 변경하는 한정 표현식이며 표현식의 형태는 다음과 같다.
[qualifier=][!]value1[,value2]...
만약 open 콜만을 추적한다면 -eopen이라는 옵션을 추가하며 이는 -e trace=open과 같다. 반대로 open 콜만을 제외하고자 한다면 -e\!open 이라고 하면 된다. !이는 특정 쉘(sh, bash, csh 등)에서 history 확장을 위해 사용하므로 이를 피하기 위해서는 backslash(\)를 사용해야 한다. 여기서 -eopen과 -e trace=open 그리고 -etrace=open은 동일한 옵션이다. 
-e trace=set 특정 시스템 콜 집합만을 추적한다. -c 옵션과 함께 사용하면 어떤 시스템 콜를 추적할지 결정하는데 유용하다.
특정 set에는 file(open,stat,chmod,unlink,...), process(fork,wait,exec...), network, signal, ipc 등이 있다. 
또한 set 대신에 -e trace=open,fork 식으로 특정 콜을 지정할 수도 있다.
예)
[root@linux root]# strace -e trace=file /usr/local/apache/bin/apachectl restart
execve("/usr/local/apache/bin/apachectl", ["/usr/local/apache/bin/apachectl", "restart"], [/* 24 vars */]) = 0
open("/etc/ld.so.preload", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=55211, ...}) = 0
open("/lib/libtermcap.so.2", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0755, st_size=13016, ...}) = 0
open("/lib/libdl.so.2", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0755, st_size=16312, ...}) = 0
open("/lib/tls/libc.so.6", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0755, st_size=1578228, ...}) = 0
open("/dev/tty", O_RDWR|O_NONBLOCK|O_LARGEFILE) = 3
open("/etc/mtab", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=212, ...}) = 0
open("/proc/meminfo", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
stat64("/root", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
stat64(".", {st_mode=S_IFDIR|0750, st_size=4096, ...}) = 0
open("/usr/local/apache/bin/apachectl", O_RDONLY|O_LARGEFILE) = 3
fstat64(255, {st_mode=S_IFREG|0755, st_size=7412, ...}) = 0
stat64("/usr/local/apache/logs/httpd.pid", {st_mode=S_IFREG|0644, st_size=6, ...}) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 3
--- SIGCHLD (Child exited) @ 0 (0) ---
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
/usr/local/apache/bin/apachectl restart: httpd restarted
-e read=set, -e write=set set에는 파일 디스크립터를 지정한다. 파일디스크립터가 3과 5라면 -e read=3,5 식으로 지정하면 된다.
-p pid 프로세스 아이디를 지정한다.
-s strsize 출력할 수 있는 최대 문자열 크기를 지정한다. 기본값은 32이고 파일명은 문자열로 간주되지 않아 모두 출력한다.
예)
기본값일 경우
[root@linux root]# strace -p 14461
Process 14461 attached - interrupt to quit
read(0, "203.xxx.xx.142 - - [28/Feb/2004:"..., 65536) = 150
time(NULL) = 1077934782
write(3, "203.xxx.xx.142 - - [28/Feb/2004:"..., 150) = 150
-s 500으로 지정할 경우
[root@linux root]# strace -s 500 -p 14461
Process 14461 attached - interrupt to quit
read(0, "203.xx.xx.142 - - [28/Feb/2004:11:17:45 +0900] \"GET / HTTP/1.1\" 406 2816 \"-\" \"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; .NET CLR 1.1.4322)\"\n", 65536) = 150
time(NULL) = 1077934665
open("/usr/local/apache/logs/transfer_log.1077934600", O_WRONLY|O_APPEND|O_CREAT, 0666) = 4
close(3) = 0
write(4, "203.xxx.xx.142 - - [28/Feb/2004:11:17:45 +0900] \"GET / HTTP/1.1\" 406 2816 \"-\" \"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.0; .NET CLR 1.1.4322)\"\n", 150) = 150
read(0,
-S sortby -c 옵션과 함께 사용되며 특정 컬럼을 정렬할 수 있다. 특정 컬럼값에는 위의 예제에도 나와 있듯이 time, calls, name 등으로 가능하다.
예)
[root@linux root]# strace -c -S name ls
execve("/bin/ls", ["ls"], [/* 24 vars */]) = 0
Desktop data.txt ls_strace qmailscanner_setup.sh
EGAVGA.BGI dmesg.log mbox signal_demo.pl
ElectricFence-2.2.2-11.i386.rpm english mremap snmp_setup.sh
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
0.85 0.000213 53 4 brk
2.09 0.000527 53 10 close
0.38 0.000096 96 1 fcntl64
1.58 0.000399 36 11 fstat64
0.71 0.000179 90 2 getdents64
0.38 0.000097 97 1 getrlimit
0.79 0.000200 100 2 ioctl
0.80 0.000201 67 3 mmap2
1.55 0.000390 98 4 munmap
4.41 0.001111 62 18 old_mmap
9.41 0.002370 215 11 1 open
3.48 0.000877 110 8 read
0.71 0.000180 45 4 2 rt_sigaction
0.12 0.000030 30 1 rt_sigprocmask
0.20 0.000051 51 1 set_thread_area
0.19 0.000048 48 1 set_tid_address
0.28 0.000071 71 1 uname
72.06 0.018155 1297 14 write
------ ----------- ----------- --------- --------- ----------------
100.00 0.025195 97 3 total