커피닉스, 시스템 엔지니어의 쉼터
  strace 사용하기 작성일 : 2005/08/15 16:03
 
  • 글쓴이 : 닥터쎌 ( http://braineyes.com )
    		•  조회수 : 19539
     
    이 문서는 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

    커피닉스, 시스템 엔지니어의 쉼터 / URL : http://coffeenix.net/board_view.php?bd_code=1142