리눅스에서 Strace를 이용한 7가지 디버깅 예제

이 페이지의 원문은 The Geek Stuff에 포스팅 된 "7 Strace Examples to Debug the Execution of a Program in Linux" 입니다. 

strace는 프로그램의 문제 해결을 도와주는 디버깅 툴입니다. strace는 특정 프로그램의 시스템 콜과 시그널을 감시하는데, 프로그램 소스 코드를 갖고 있지 않거나, 프로그램의 시작에서 종료될 때까지의 실행 시퀀스를 디버깅할 때 유용하게 사용할 수 있습니다. 

이 문서에서는 7가지의 strace 예제를 소개합니다.

1. 바이너리 추적하기
strace 명령어를 이용하면 (실행 가능한)바이너리를 추적할 수 있습니다. 다음 예제는 리눅스 명령어인 "ls"에 대한 strace 결과를 보여줍니다. 

$  strace ls
execve("/bin/ls", ["ls"], [/* 21 vars */]) = 0
brk(0)                                  = 0x8c31000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb78c7000
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=65354, ...}) = 0
...
...
...

2. -e 옵션을 사용해 특정 시스템 콜 추적하기
strace는 기본적으로 주어진 바이너리의 모든 시스템 콜을 보여줍니다. 아래와 같이 -e 옵션을 사용하면 특정 시스템 콜만 볼 수 있습니다.
 

$ strace -e open ls
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib/libselinux.so.1", O_RDONLY)  = 3
open("/lib/librt.so.1", O_RDONLY)       = 3
open("/lib/libacl.so.1", O_RDONLY)      = 3
open("/lib/libc.so.6", O_RDONLY)        = 3
open("/lib/libdl.so.2", O_RDONLY)       = 3
open("/lib/libpthread.so.0", O_RDONLY)  = 3
open("/lib/libattr.so.1", O_RDONLY)     = 3
open("/proc/filesystems", O_RDONLY|O_LARGEFILE) = 3
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
open(".", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 3
Desktop  Documents  Downloads  examples.desktop  libflashplayer.so
Music  Pictures  Public  Templates  Ubuntu_OS  Videos

위 결과는 ls 명령어에 대한 open 시스템 콜만 출력하는 것을 보여줍니다. 출력의 마지막 부분에 ls 명령어의 결과도 출력되는 것을 볼 수 있습니다.

"-e trace=" 옵션을 사용하면 여려 개의 시스템 콜을 출력할 수 있습니다. 다음 예제는 open과 read 시스템 콜 추적을 보여줍니다.

$ strace -e trace=open,read ls /home
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib/libselinux.so.1", O_RDONLY)  = 3
read(3, "\177ELF\1\1\1\3\3\1\260G004"..., 512) = 512
open("/lib/librt.so.1", O_RDONLY)       = 3
read(3, "\177ELF\1\1\1\3\3\1\300\30004"..., 512) = 512
..
open("/lib/libattr.so.1", O_RDONLY)     = 3
read(3, "\177ELF\1\1\1\3\3\1\360\r004"..., 512) = 512
open("/proc/filesystems", O_RDONLY|O_LARGEFILE) = 3
read(3, "nodev\tsysfs\nnodev\trootfs\nnodev\tb"..., 1024) = 315
read(3, "", 1024)                       = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
open("/home", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 3
bala

3. -o 옵션을 사용해 결과를 파일에 저장하기
다음 예제는 strace 결과를 output.txt 파일에 저장하는 것을 보여줍니다.

$ strace -o output.txt ls
Desktop  Documents  Downloads  examples.desktop  libflashplayer.so
Music  output.txt  Pictures  Public  Templates  Ubuntu_OS  Videos

$ cat output.txt
execve("/bin/ls", ["ls"], [/* 37 vars */]) = 0
brk(0)                                  = 0x8637000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7860000
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=67188, ...}) = 0
...
...

4. -p 옵션을 사용해 실행 중인 리눅스 프로세스에 strace 실행시키기
프로세스 ID를 사용해 이미 실행 중인 프로그램에 strace를 실행 시킬 수 있습니다. 우선, ps 명령어를 사용해 프로그램의 PID를 알아냅니다. 

예를 들어, 현재 실행 중인 파이어폭스 프로그램을 추적하길 원한다면 다음과 같이 파이어폭스 프로그램의 PID를 먼저 알아내야 됩니다.
 

$ ps -C firefox-bin
  PID TTY          TIME CMD
1725 ?        00:40:50 firefox-bin

알아낸 프로세스 ID에 strace를 적용하기 위해 다음과 같이 -p 옵션을 사용합니다. 

$  sudo strace -p 1725 -o firefox_trace.txt

$ tail -f firefox_trace.txt

이제 파이어폭스 프로세스의 strace가 실행되고, 결과는 firefox_trace.txt 파일에 저장 됩니다. 이 파일에 tail 명령어를 이용하면 파이어폭스의 추적 정보를 살펴볼 수 있습니다. 

주어진 프로세스에 대한 UID가 현재 사용자의 UID와 매칭되지 않으면 다음과 같은 에러가 발생됩니다.

$  strace -p 1725 -o output.txt
attach: ptrace(PTRACE_ATTACH, ...): Operation not permitted
Could not attach to process.  If your uid matches the uid of the target
process, check the setting of /proc/sys/kernel/yama/ptrace_scope, or try
again as the root user.  For more details, see /etc/sysctl.d/10-ptrace.conf

5. -t 옵션을 사용해 각 Trace에 대한 시간 정보 출력하기
다음과 같이 -t 옵션을 사용해 strace의 라인 별 시간 정보를 출력할 수 있습니다.

$ strace -t -e open ls /home
20:42:37 open("/etc/ld.so.cache", O_RDONLY) = 3
20:42:37 open("/lib/libselinux.so.1", O_RDONLY) = 3
20:42:37 open("/lib/librt.so.1", O_RDONLY) = 3
20:42:37 open("/lib/libacl.so.1", O_RDONLY) = 3
20:42:37 open("/lib/libc.so.6", O_RDONLY) = 3
20:42:37 open("/lib/libdl.so.2", O_RDONLY) = 3
20:42:37 open("/lib/libpthread.so.0", O_RDONLY) = 3
20:42:37 open("/lib/libattr.so.1", O_RDONLY) = 3
20:42:37 open("/proc/filesystems", O_RDONLY|O_LARGEFILE) = 3
20:42:37 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
20:42:37 open("/home", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|O_CLOEXEC) = 3
bala

6. -r 옵션을 사용해 시스템 콜의 상대 시간 정보 출력하기
strace는 -r 옵션을 사용해 아래와 같은 시스템 콜의 실행 시간을 출력할 수 있습니다. 

$ strace -r ls
     0.000000 execve("/bin/ls", ["ls"], [/* 37 vars */]) = 0
     0.000846 brk(0)                    = 0x8418000
     0.000143 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
     0.000163 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb787b000
     0.000119 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
     0.000123 open("/etc/ld.so.cache", O_RDONLY) = 3
     0.000099 fstat64(3, {st_mode=S_IFREG|0644, st_size=67188, ...}) = 0
     0.000155 mmap2(NULL, 67188, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb786a000
     ...
     ...

7. -c 옵션을 사용해 시스템 콜 통계 정보 생성하기 
strace에 "-c" 옵션을 사용하면 유용한 통계 정보를 제공받을 수 있습니다. 아래의 "calls" 열은 특정 시스템 콜이 얼마나 많이 실행됐는지를 나타냅니다.

$ strace -c ls /home
bala
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0         9           read
  -nan    0.000000           0         1           write
  -nan    0.000000           0        11           open
  -nan    0.000000           0        13           close
  -nan    0.000000           0         1           execve
  -nan    0.000000           0         9         9 access
  -nan    0.000000           0         3           brk
  -nan    0.000000           0         2           ioctl
  -nan    0.000000           0         3           munmap
  -nan    0.000000           0         1           uname
  -nan    0.000000           0        11           mprotect
  -nan    0.000000           0         2           rt_sigaction
  -nan    0.000000           0         1           rt_sigprocmask
  -nan    0.000000           0         1           getrlimit
  -nan    0.000000           0        25           mmap2
  -nan    0.000000           0         1           stat64
  -nan    0.000000           0        11           fstat64
  -nan    0.000000           0         2           getdents64
  -nan    0.000000           0         1           fcntl64
  -nan    0.000000           0         2         1 futex
  -nan    0.000000           0         1           set_thread_area
  -nan    0.000000           0         1           set_tid_address
  -nan    0.000000           0         1           statfs64
  -nan    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                   114        10 total