-
strace란 시스템 콜 함수들과 시그널 처리에 대해서 트레이스할 수 있는 명령어입니다.
권한 오류 문제나, 시스템 자원 부족등의 실행오류가 나타날 때 불친절한 프로그램들은 결과를 보여주지 않지만, strace를 해보면 시스템 콜 함수들이 실패 할 때의 오류 원인들이 함께 나타나기 때문에 프로그램의 디버깅에 활용됩니다.
트레이스를 통하여 어떤 시스템 함수를 호출하고 시그널 처리되는지 볼수 있기 때문에 프로그램이 어떤 동작을 하는지 유추 할 수도 있다.
man page를 보면 손쉽게 해당 명령어의 목적과 자세한 사용방법, 주의사항이 나온다.(잘 모르는게 나오면 일단 구글링이 아니라 man 명령어를 실행시키는 습관을 들이자)
man strace
NAME strace - trace system calls and signals SYNOPSIS strace [ -dffhiqrtttTvxx ] [ -acolumn ] [ -eexpr ] ... [ -ofile ] [ -ppid ] ... [ -sstrsize ] [ -uusername ] [ -Evar=val ] ... [ -Evar ] ... [ command [ arg ... ] ] strace -c [ -eexpr ] ... [ -Ooverhead ] [ -Ssortby ] [ command [ arg ... ] ] DESCRIPTION In the simplest case strace runs the specified command until it exits. It intercepts and records the system calls which are called by a process and the signals which are received by a process. The name of each system call, its arguments and its return value are printed on standard error or to the file specified with the -o option. strace is a useful diagnostic, instructional, and debugging tool. System administrators, diagnosticians and trouble-shooters will find it invalu- able for solving problems with programs for which the source is not readily available since they do not need to be recompiled in order to trace them. Students, hackers and the overly-curious will find that a great deal can be learned about a system and its system calls by tracing even ordinary programs. And programmers will find that since system calls and signals are events that happen at the user/kernel interface, a close examination of this boundary is very useful for bug isolation, sanity checking and attempting to capture race conditions. Each line in the trace contains the system call name, followed by its arguments in parentheses and its return value. An example from stracing the command ``cat /dev/null'' is: open("/dev/null", O_RDONLY) = 3 Errors (typically a return value of -1) have the errno symbol and error string appended. open("/foo/bar", O_RDONLY) = -1 ENOENT (No such file or directory) Signals are printed as a signal symbol and a signal string. An excerpt from stracing and interrupting the command ``sleep 666'' is: sigsuspend([]--- SIGINT (Interrupt) --- +++ killed by SIGINT +++ Arguments are printed in symbolic form with a passion. This example shows the shell performing ``>>xyzzy'' output redirection: open("xyzzy", O_WRONLY|O_APPEND|O_CREAT, 0666) = 3 Here the three argument form of open is decoded by breaking down the flag argument into its three bitwise-OR constituents and printing the mode value in octal by tradition. Where traditional or native usage differs from ANSI or POSIX, the latter forms are preferred. In some cases, strace output has proven to be more readable than the source. ※ man 페이지는 항상 옳다.
예1) date 명령어
morenice@ubuntu:~$ starce date
execve("/bin/date", ["date"], [/* 34 vars */]) = 0 brk(0) = 0x610000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b4c8789a000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b4c8789b000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) open("/etc/ld.so.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=54407, ...}) = 0 mmap(NULL, 54407, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c8789c000 close(3) = 0 open("/lib/librt.so.1", O_RDONLY) = 3 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300\"\0\0\0\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=35688, ...}) = 0 mmap(NULL, 2132968, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x2b4c87a9b000 mprotect(0x2b4c87aa3000, 2093056, PROT_NONE) = 0 mmap(0x2b4c87ca2000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x2b4c87ca2000 close(3) = 0 open("/lib/libc.so.6", O_RDONLY) = 3 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220\334\1\0\0\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=1293456, ...}) = 0 mmap(NULL, 3399928, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x2b4c87ca4000 mprotect(0x2b4c87dda000, 2093056, PROT_NONE) = 0 mmap(0x2b4c87fd9000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x135000) = 0x2b4c87fd9000 mmap(0x2b4c87fde000, 16632, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x2b4c87fde000 close(3) = 0 open("/lib/libpthread.so.0", O_RDONLY) = 3 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260W\0\0\0\0\0\0"..., 832) = 832 fstat(3, {st_mode=S_IFREG|0755, st_size=131897, ...}) = 0 mmap(NULL, 2204528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x2b4c87fe3000 mprotect(0x2b4c87ff8000, 2097152, PROT_NONE) = 0 mmap(0x2b4c881f8000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x15000) = 0x2b4c881f8000 mmap(0x2b4c881fa000, 13168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x2b4c881fa000 close(3) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b4c881fe000 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b4c881ff000 arch_prctl(ARCH_SET_FS, 0x2b4c881ff040) = 0 mprotect(0x2b4c881f8000, 4096, PROT_READ) = 0 mprotect(0x2b4c87fd9000, 16384, PROT_READ) = 0 mprotect(0x2b4c87ca2000, 4096, PROT_READ) = 0 mprotect(0x60e000, 4096, PROT_READ) = 0 mprotect(0x2b4c87a99000, 4096, PROT_READ) = 0 munmap(0x2b4c8789c000, 54407) = 0 set_tid_address(0x2b4c881ff0d0) = 25771 set_robust_list(0x2b4c881ff0e0, 0x18) = 0 rt_sigaction(SIGRTMIN, {0x2b4c87fe8320, [], SA_RESTORER|SA_SIGINFO, 0x2b4c87ff0ed0}, NULL, 8) = 0 rt_sigaction(SIGRT_1, {0x2b4c87fe83a0, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x2b4c87ff0ed0}, NULL, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0 getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0 brk(0) = 0x610000 brk(0x631000) = 0x631000 open("/usr/lib64/locale/locale-archive", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/share/locale/locale.alias", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=2586, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b4c8789c000 read(3, "# Locale name alias data base.\n#"..., 4096) = 2586 read(3, "", 4096) = 0 close(3) = 0 munmap(0x2b4c8789c000, 4096) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_IDENTIFICATION", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_IDENTIFICATION", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=310, ...}) = 0 mmap(NULL, 310, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c8789c000 close(3) = 0 open("/usr/lib64/gconv/gconv-modules.cache", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=25488, ...}) = 0 mmap(NULL, 25488, PROT_READ, MAP_SHARED, 3, 0) = 0x2b4c8789d000 close(3) = 0 futex(0x2b4c87fddf18, FUTEX_WAKE, 2147483647) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_MEASUREMENT", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_MEASUREMENT", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0 mmap(NULL, 23, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c878a4000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_TELEPHONE", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_TELEPHONE", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 mmap(NULL, 56, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c878a5000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_ADDRESS", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_ADDRESS", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 mmap(NULL, 127, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c878a6000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_NAME", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_NAME", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=62, ...}) = 0 mmap(NULL, 62, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c878a7000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_PAPER", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_PAPER", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=34, ...}) = 0 mmap(NULL, 34, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c878a8000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_MONETARY", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_MONETARY", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=294, ...}) = 0 mmap(NULL, 294, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c878a9000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_COLLATE", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_COLLATE", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=584938, ...}) = 0 mmap(NULL, 584938, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c878aa000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_TIME", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_TIME", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=2198, ...}) = 0 mmap(NULL, 2198, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c87939000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_NUMERIC", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_NUMERIC", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=54, ...}) = 0 mmap(NULL, 54, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c8793a000 close(3) = 0 open("/usr/lib64/locale/ko_KR.UTF-8/LC_CTYPE", O_RDONLY) = -1 ENOENT (No such file or directory) open("/usr/lib64/locale/ko_KR.utf8/LC_CTYPE", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=656220, ...}) = 0 mmap(NULL, 656220, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2b4c8793b000 close(3) = 0 clock_gettime(CLOCK_REALTIME, {1308099307, 534157216}) = 0 open("/etc/localtime", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=380, ...}) = 0 fstat(3, {st_mode=S_IFREG|0644, st_size=380, ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b4c879dc000 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\5\0\0\0\0"..., 4096) = 380 lseek(3, -228, SEEK_CUR) = 152 read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\6\0\0\0\0"..., 4096) = 228 close(3) = 0 munmap(0x2b4c879dc000, 4096) = 0 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 6), ...}) = 0 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b4c879dc000 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=380, ...}) = 0 write(1, "2011. 06. 15. (\354\210\230) 09:55:07 KST"..., 332011. 06. 15. (수) 09:55:07 KST ) = 33 close(1) = 0 munmap(0x2b4c879dc000, 4096) = 0 close(2) = 0 exit_group(0) = ?
위의 결과에서 /bin/date 명령어가 execve 시스템콜로 호출되었고 중간에 open으로 통해 /etc/localtime을 읽는 부분이 나오며 write 시스템 콜을 통하여 출력을 하는 것을 확인할 수 있다.
※ /etc/locatime은 시스템의 timezone정보가 저장됨.
예2) 디버깅
이번엔 디버깅의 예로, 작업을 하다가 왜 daemon이 실행이 안되나 하고 있다가 strace 명령어로 보니 conf 파일이 없음을 확인하였다.
다음은 결과 화면이다.
( -f 옵션은 자식 프로세스까지 trace하는 옵션으로, daemon은 fork의 과정이 포함되어 있기 때문에 해당 옵션을 포함시킴.)
strace -f ./nm_daemon
.. .. .. [pid 6186] epoll_create(100) = 38 [pid 6186] epoll_ctl(38, EPOLL_CTL_ADD, 37, {EPOLLIN|EPOLLERR, {u32=37, u64=37}}) = 0 [pid 6186] epoll_wait(38, {}, 20, 1000) = 0 [pid 6186] epoll_wait(38,[pid 6149] <... nanosleep resumed> {1, 0}) = 0 [pid 6149] creat("/var/tmp/.init_lock", 0777) = 39 [pid 6149] flock(39, LOCK_EX|LOCK_NB) = 0 [pid 6149] flock(39, LOCK_UN) = 0 [pid 6149] close(39) = 0 [pid 6149] access("./conf/nm.conf", F_OK) = 0 [pid 6149] access("./conf/func.conf", F_OK) = -1 ENOENT (No such file or directory) [pid 6149] close(36) = 0 [pid 6149] exit_group(1) = ? Process 6149 detached upeek: ptrace(PTRACE_PEEKUSER,6151,120,0): No such process Process 6151 detached
위의 결과에서 No such file or directroy 이후에 exit 되는걸 확인할 수 있다. trace를 통하여 이렇게 권한 문제, 설정 문제, 시스템의 문제등을 문제점들을 디버깅 할 수 있다.
※ strace --help 를 하면 여러가지 옵션을 확인 할수 있다. 한번씩 확인해보시길 :D
strace -i : print 시스템 콜 instruction pointer
strace -c : print 시스템콜, 시간, 오류 count
반응형