strace 사용하기

출처: http://coffeenix.net/ 프로그래밍게시판

작성자: 닥터쎌 ( http://braineyes.com )

strace 사용하기

이 문서는 strace 매뉴얼을 바탕으로 예를 들어가면서 설명한 글입니다.
설명문이라 존대는 사용하지 않았으므로 양해하시기 바랍니다.
개인적으로는 qmail, vpopmail, apache 디버깅에 유용하게 사용한 적이 있는데
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