Original Link : The Magic of Strace (by Chad Fowler)
Thanks to Chad Fowler! this document is korean translated version of "Chad Fowler's great writing"
If you read this and got some insight, visit and read more posts at http://chadfowler.com/
원 저자이신, 채드 파울러(Chad Fowler)님의 허락을 얻어 번역한 글입니다.
내가 IT 경력을 쌓은지 얼마되지 않았을 때, 동료와 나는 며칠에 걸쳐 로터스 도미노 서버(Lotus Domino Server) 장애와 씨름하고 있는 팀을 지원하기 위해 멤피스(Memphis)에서 올란도(Orlando)까지 비행기를 타고 가야 했다. 올란도에 있는 팀은 장애를 해결하지 못하고 며칠째 아무 곳에도 가지 못하며 옴쭉달짝을 못하고 있는 상황이었다. 나는 그들이 나와 동료가 도움을 될거라 생각한다는 사실을 믿기 어려웠다. 우리는 로터스 도미노에 대해서는 아무 것도 모르는 상태였기 때문이다. 하지만, 나는 UNIX 를 열심히 공부했고 또 잘 다룰 줄 알았다. 아무래도 그들은 자포자기 상태였던 듯 하다.
로터스 도미노는 소스가 공개되지 않는 블랙박스 형태의 "그룹웨어(groupware)" 서버였다. 그 때 문제가 정확히 무엇이었는지 기억 나지는 않지만, 데이터베이스의 파일들을 제대로 읽고 쓰지 못하는 문제를 해결했던 것 같고, 확실한 것은 로터스 기술팀의 고급(escalated) 기술지원으로도 문제를 해결하지 못했었다.
그 경험은 내 경력을 거쳐 익힌 수많은 학습 중에 가장 깊이 있는 것 중에 하나였다. 내가 사용하는 다양한 유닉스 툴(tool) 중에서 지금까지도 가장 중요하게 여기는 strace.* 명령을 그 때 배웠다.
근래에 들어서도 프로그래머이자 시스템 엔지니어로서 일하면서 거의 매일 strace 혹은 그와 유사한 명령들을 사용하고 있다. 이 글에서 왜 그리고 어떻게 strace 명령을 사용하는지 설명하고, 그리고 너무나도 훌륭하고 강력한 작은 도구를 활용하는 몇가지 팁(tip)을 보여주고자 한다.
strace 는 무엇인가 (What is strace?)
strace 는 특정 프로세스와 자식 프로세스의 시스템 호출(system call)과 프로세스에 전달되는 시그널(signal)을 추적할 수 있는 명령행 도구(command line tool)이다. strace 명령을 이용해 프로그램을 시작할 수도 있고, 실행 중인 프로그램의 시스템 호출을 추적하는데 사용할 수도 있다. 간단한 예제를 살펴보자. 다음과 같은 간단한 C 프로그램을 작성했다고 가정하자.
[traceme.c]
#include <stdio.h>
void main() {
printf("hi\n");
}
많은 기능을 담고 있지는 않다. 그냥 화면에 "Hi"라는 문자열을 프린트 할 뿐이다. 프로그램을 컴파일한 후에, strace 명령을 이용해 실행해보면 프로그램이 수행하는 시스템 호출을 모두 볼 수 있다.
$ strace -s 2000 -f ./traceme
execve("./g", ["./g"], [/* 25 vars */]) = 0
brk(0) = 0x1816000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2ffa263000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=35614, ...}) = 0
mmap(NULL, 35614, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f2ffa25a000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
... (중략) ...
write(1, "hi\n", 3hi
) = 3
exit_group(3)
프로그램을 실행하기 위해, strace 명령과 프로그램 명칭을 입력했다. (더불어, 프로그램 실행에 필요한 인자를 추가할 수 있다.) 위 예시에서는 '-s' 옵션(flag)를 추가해 strace가 출력하는 문자열의 최대 크기를 지정했다. 이렇게 하는 것이 함수들의 인자를 조회하는데 도움이 된다. 여기서는 임의로 2000을 지정했는데, 이 값은 우리가 실행하는 프로그램에서 보고자 하는 정보를 얻는데 충분하다. 기본값은 32인데, 내 경험으로는 프로그램을 추적하는 과정에서 필요한 정보를 캐내기에는 절대적으로 부족하다. 또한, '-f' 옵션을 지정했으며, 이는 strace로 하여금 우리가 실행한 프로세스의 자식 프로세스도 추적하라고 지시하는 것이다. 위 예제에서는 자식 프로세스가 없지만, strace를 사용할 때는 일반적으로 프로세스의 자식까지 추적하도록 설정하는 습관을 가지는 것이 프로그램의 실행 중에 벌어지는 모든 것을 알 수 있기에 권장한다.
명령을 실행하고 나면, 좀 장황한 시스템 호출 기록들을 모두 보게 된다. 일부(거의 모두?)는 마치 횡설수설하는 것처럼 보인다. 들여다 봐도 대부분 이해할 수는 없겠지만, 그리 오래지 않아 쓸만한 정보들을 찾아낼 수 있을 것이다.
추적(trace)의 첫번째 라인은 execve() 호출이다. 놀라울 것도 없이, execve() 이 수행하는 것은 프로그램을 실행하는 것이다. 프로그램의 경로와 인자(argument)의 배열, 그리고 프로그램 설정을 위한 환경 변수 목록을 받아들인다. (너무 데이터가 많기 때문에 출력 결과에서는 생략된 형태로 보인다.)
마지막 2 라인은 알아볼 수 있는 또 다른 정보를 제공한다. 먼저, write() 호출은 C 프로그램에 포함된 "hi\n" 문자열을 포함하고 있다. write() 의 첫번째 인자는 문자열이 출력되는 대상 파일 디스크립터(file descriptor)이다. 여기서는 '1'이며, 프로세스의 표준 출력 스트림(standard output stream)을 의미한다. write 호출 이후 (알아보기 약간 어려울 수 있는데 실제 화면 출력과 strace 명령의 출력이 섞여서 보이기 때문이다), 프로그램은 exit_gorup() 을 호출한다. 이 함수는 exit() 와 비슷하게 동작하나, 프로세스의 모든 스레드(thread)를 종료한다.
execve() 호출과 write() 호출 사이에 존재하는 모든 호출들은 대체 무엇인가? 메인 프로그램이 시작하기 전에 모든 표준 C 라이브러리들을 호출하는 작업들이다. 이런 호출들은 기본적으로 런타임(runtime)을 초기화 하는 작업이다. 눈여겨 들여다 보면 몇가지 파일들을 점검하고, 파일들에 접근 가능한지 확인한 후 파일을 연다. 그리고, 그것들을 메모리 위치에 매핑(mapping)한 후에 닫는다.
한가지 중요한 힌트 : 이러한 함수들 모두 문서화 되어 있으며, man 페이지를 이용해 읽어볼 수 있다. 만일, mmap()이 무엇을 하는 것인지 모른다면, "man mmap" 명령을 실행해 보면 도움말(정의/사용법/옵션 등)을 찾아볼 수 있다.
위에 예시한 strace 출력 결과에 나오는 모든 함수를 찾아보고 공부하기 바란다. 책보다 쉽게 배울 수 있다!
현실에서 실행 중인 프로세스를 추적하기 (Tracing a running, real-world process)
내가 strace 같은 툴을 필요로 하는 순간은 이미 실행 중인 프로세스가 정상적으로 동작하지 않을 때이다. 일반적인 상황에서는 이러한 프로세스가 초기화 시스템(init system)에 의해 구동되기 때문에 문제해결을 하기가 여간 힘든 것이 아니다. 따라서, 로그를 분석하거나 모니터링 도구를 외부에서 구해야만 한다.
strace 는 이미 구동 중인 프로세스의 내부 동작을 손쉽게 들여다 볼 수 있게끔 해준다. 운영 중인 루비 유니콘 프로세스 (루비 웹 서버)에 문제가 있고, 프로세스의 로그를 들여다 봐서는 도저히 쓸만한 정보를 얻을 수 없는 상태라고 가정해보자. strace 의 '-p' 옵션을 사용해 프로세스에 연결할 수 있다. 운영 중인 서버의 가동율이 높아서 꽤 많은 출력이 발생할 것이라고 예상되면 '-o' 옵션을 사용해 출력 결과를 로그 파일에 저장할 수 있다.
$ sudo strace -o /tmp/strace.out -s 2000 -fp 12152 Process 12152 attached with 4 threads - interrupt to quit ^CProcess 12152 detached Process 12155 detached Process 12160 detached Process 3146 detached
(strace 를 이용해 실행 중인 프로세스를 추적하니) 단 몇 초 만에 로그 파일의 크기는 9,000 라인을 넘어 버렸다. 아래에 어쩌면 흥미로울지도 모르는 로그 일부를 캡쳐(capture) 해두었다.
3419 select(16, [14 15], NULL, [7 8], {29, 0}) = 1 (in [14], left {28, 987147}) 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 122710542}) = 0 3419 fcntl(14, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 3419 accept4(14, 0, NULL, SOCK_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) 3419 getppid() = 25937 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 123156611}) = 0 3419 clock_gettime(CLOCK_MONOTONIC, {92751, 940365496}) = 0 3419 select(16, [14 15], NULL, [7 8], {29, 0}) = 1 (in [14], left {28, 972271}) 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 152520833}) = 0 3419 fcntl(14, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 3419 accept4(14, 0, NULL, SOCK_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) 3419 getppid() = 25937 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 152849344}) = 0 3419 clock_gettime(CLOCK_MONOTONIC, {92751, 970066349}) = 0 3419 select(16, [14 15], NULL, [7 8], {29, 0}) = 1 (in [14], left {28, 958562}) 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 195372960}) = 0 3419 fcntl(14, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 3419 accept4(14, 0, NULL, SOCK_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) 3419 getppid() = 25937 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 195710712}) = 0 3419 clock_gettime(CLOCK_MONOTONIC, {92752, 12883582}) = 0 3419 select(16, [14 15], NULL, [7 8], {29, 0}) = 1 (in [14], left {28, 956099}) 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 240006588}) = 0 3419 fcntl(14, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 3419 accept4(14, 0, NULL, SOCK_CLOEXEC) = 13 3419 fstat(13, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 3419 recvfrom(13, "GET /a/check HTTP/1.0\r\nX-Forwarded-For: 127.0.0.1\r\nHost: localhost\r\nX-Request-Start: t=1390981158239000\r\nConnection: close\r\nUser-Agent: curl/7.29.0\r\nAccept: */*\r\n\r\n", 16384, MSG_DONTWAIT, NULL, NULL) = 167 3419 ppoll([{fd=13, events=POLLOUT}], 1, NULL, NULL, 8) = 1 ([{fd=13, revents=POLLOUT}]) 3419 write(13, "HTTP", 4) = 4 3419 ppoll([{fd=13, events=POLLOUT}], 1, NULL, NULL, 8) = 1 ([{fd=13, revents=POLLOUT}]) 3419 write(13, "/1.1 ", 5) = 5 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 241130051}) = 0 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 241273452}) = 0 3419 stat("/opt/app/tmp/cache/CE5/510/http%3A%2F%2Flocalhost%2Fa%2Fcheckh%3F", 0x7fffcb874db0) = -1 ENOENT (No such file or directory) 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 241762672}) = 0 3419 clock_gettime(CLOCK_REALTIME, {1390981158, 242012184}) = 0 3419 sendto(16, "Q\0\0\0\rSELECT 1\0", 14, MSG_NOSIGNAL, NULL, 0) = 14 3419 poll([{fd=16, events=POLLIN|POLLERR}], 1, 4294967295) = 1 ([{fd=16, revents=POLLIN}]) 3419 recvfrom(16, "T\0\0\0!\0\1?column?\0\0\0\0\0\0\0\0\0\0\27\0\4\377\377\377\377\0\0D\0\0\0\v\0\1\0\0\0\0011C\0\0\0\rSELECT 1\0Z\0\0\0\5I", 65536, 0, NULL, NULL) = 66 3419 rt_sigprocmask(SIG_SETMASK, ~[HUP INT QUIT KILL USR1 SEGV USR2 TERM CHLD STOP TTIN TTOU VTALRM WINCH RTMIN RT_1], NULL, 8) = 0
모든 라인을 분석할 수는 없지만, 일단 첫번째 라인을 확인해보면, select() 호출이다. 프로그램은 select()를 이용해 시스템에 위치한 파일 디스크립터(file descriptor)의 변화(활동)를 감시한다. select() man 페이지에 의하면, 두번째 인자는 읽기 처리를 감시하기 위한 파일 디스크립터 리스트이다. select() 는 설정 가능한 시간만큼 블록(block)되며 파일 디스크립터의 활동을 주시하고, 활동이 감지된 파일의 갯수를 반환한다.
일단 나머지 인자들에 대해서는 무시하고, select() 호출이 14 및 15번 파일 디스크립터의 읽기 처리를 감시하고 (추적 결과의 오른편을 주시할 것), '1' 값을 반환한다. strace는 몇가지 시스템 호출에 대한 정보를 추가로 제공하기 때문에 우리는 가공되지 않은(raw) 결과 뿐만 아니라, 어떤 파일 디스크립터(14)가 변화했는지를 파악할 수 있다. 가끔은 시스템 호출에 대한 가공되지 않은 정보가 필요한 경우가 있으며, 이럴 때는 "-e raw=select" 옵션을 strace 명령에 추가하면 된다. 이렇게 하면 strace 가 select() 호출에 대한 가공되지 않은 형태의 실행 결과를 출력한다.
그렇다면, 14 및 15 파일 디스크립터는 무엇인가? 무언지 알 수 없다면, 앞서 확인한 단서는 무용지물이다. lsof 명령을 이용해 어떤 파일인지 확인해 보자.
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME ruby 3419 app DEL REG 0,4 26473410 /dev/zero ruby 3419 app 0r CHR 1,3 0t0 14 /dev/null ruby 3419 app 1w REG 202,1 18 159903 /opt/app/log/unicorn-out.log ruby 3419 app 2w REG 202,1 621 159902 /opt/app/log/unicorn-err.log ruby 3419 app 3r FIFO 0,8 0t0 36967385 pipe ruby 3419 app 4w FIFO 0,8 0t0 36967385 pipe ruby 3419 app 5r CHR 1,3 0t0 14 /dev/null ruby 3419 app 6w CHR 1,3 0t0 14 /dev/null ruby 3419 app 7r FIFO 0,8 0t0 36967386 pipe ruby 3419 app 8w FIFO 0,8 0t0 36967386 pipe ruby 3419 app 9w FIFO 0,8 0t0 26472351 pipe ruby 3419 app 10u IPv4 36967388 0t0 TCP some-internal-host:60490->some-internal-host:6379 (ESTABLISHED) ruby 3419 app 11u unix 0xffff8800e8589a00 0t0 26473540 socket ruby 3419 app 12u IPv4 36967390 0t0 TCP some-internal-host:53691->some-internal-host:6379 (ESTABLISHED) ruby 3419 app 14u unix 0xffff8800e80a23c0 0t0 26473408 /opt/app/sockets/unicorn.socket ruby 3419 app 15u IPv4 26473409 0t0 TCP *:http-alt (LISTEN) ruby 3419 app 16u IPv4 36967393 0t0 TCP some-internal-host:49929->some-internal-host:postgresql (ESTABLISHED) ruby 3419 app 17u IPv4 36968294 0t0 UDP *:42720 ruby 3419 app 18u IPv4 36969521 0t0 TCP some-internal-host:43407->some-internal-host:mysql (ESTABLISHED) ruby 3419 app 19u IPv4 36969774 0t0 TCP some-internal-host:53698->some-internal-host:6379 (ESTABLISHED) ruby 3419 app 21u IPv4 36969842 0t0 TCP some-internal-host:33576->some-internal-host:mysql (ESTABLISHED) ruby 3419 app 22u IPv4 36969020 0t0 TCP some-internal-host:52827->some-internal-host:postgresql (ESTABLISHED) ruby 3419 app 23u IPv4 36969112 0t0 TCP some-internal-host:33209->178.236.7.109:https (ESTABLISHED) ruby 3419 app 24u IPv4 36969137 0t0 TCP some-internal-host:35439->some-internal-host:mysql (ESTABLISHED) ruby 3419 app 25u IPv4 36969148 0t0 TCP some-internal-host:49847->some-internal-host:mysql (ESTABLISHED) ruby 3419 app 26u IPv4 36970664 0t0 TCP some-internal-host:35217->some-internal-host:mysql (ESTABLISHED) ruby 3419 app 27u IPv4 54296608 0t0 TCP some-internal-host:48903->some-external-host.com:http (ESTABLISHED)
"FD"라는 타이틀로 표시된 lsof 출력의 4번째 컬럼을 보면, 프로그램이 사용하는 파일 디스크립터라는 것을 알 수 있다. 그렇다! 14, 15 는 유니콘(Unicorn) 웹 서버가 listen 하고 있는 TCP 및 UNIX 소켓이다. 프로세스가 select() 를 이용해서 포트를 주시하고 있다는 말이 된다. 그리고, UNIX 소켓 (파일 디스크립터 14)를 통해서 통신이 발생하고 있다는 것 또한 알 수 있다.
다음으로, 우리는 몇 개의 시스템 호출을 통해 UNIX 소켓을 통해 수신되는 통신을 받아들이려 시도하고 있고, EAGAIN이 반환되고 있다는 것을 확인할 수 있다. 이것은 멀티 프로세싱 서버(multi processing server)에서 정상적인 동작 방식이다. 프로세스는 수신되는 데이터를 대기(감시)하고, 읽기를 반복한다.
결과적으로 accept4() 호출 이후에 파일 디스크립터(13)가 오류 없이 반환된다. 이제 요청(request)을 처리할 시간이다. 먼저 프로세스는 파일 디스크립터의 정보를 fstat() 호출을 이용해 확인한다. fstat()의 두번째 인자는 'stat' 구조체이며, fstat() 호출이 파일 상태 정보를 채워준다. 모드(S_IFSOCK)와 크기(일반적인 파일이 아니므로 0으로 보인다)를 확인할 수 있다. 짐작컨데 소켓 파일 디스크립터일 것이고, 프로세스는 recvform() 호출을 이용해 데이터를 읽어낸다.
흥미로운 점에 대해 생각해보기 (Here’s where things get interesting)
fstat() 처럼 recvform()의 첫번째 인자는 데이터를 읽기 위한 파일 디스크립터이며, 두번째 인자는 읽어들인 데이터를 담을 버퍼이다. 이것이 프로그램을 디버깅할 때 진정 흥미로운 포인트다 : 웹 서버 프로세스로 전송된 HTTP 요청 데이터 전체를 볼 수 있다! 가독성을 높인 다음 예시를 참고하기 바란다. :
GET /a/check HTTP/1.0 X-Forwarded-For: 127.0.0.1 Host: localhost X-Request-Start: t=1390981158239000 Connection: close User-Agent: curl/7.29.0 Accept: */*
충분히 제어할 수 없는 프로세스에 대한 문제해결(troubleshooting)을 시도할 경우, 위와 같은 정보는 아주 큰 도움이 된다. recvfrom() 호출의 응답 데이터는 수신한 데이터의 바이트 수이다 (167). 이제 응답(response)할 시간이다.
프로세스는 먼저 ppoll을 이용해 시스템 측에 소켓에 쓸 수 있는 시점이 언제인지를 확인한다. ppoll()은 파일 디스크립터 목록을 받고, 이벤트를 설정한다. 여기서는 프로세스가 소켓이 블록 해지 되고(POLLOUT) 쓸 수 있는 시점에 통지(notified) 받기를 요청한다. 소켓에 쓸 수 있다고 통지되면, HTTP 응답 헤더를 write() 호출을 이용해 쓰기 시작한다.
다음으로 유니콘 프로세스의 내부 라우팅(routing) 동작이 어떻게 동작하는지를 들여다 볼 수 있다. stat() 을 이용해 요청된 주소(URL 경로)를 위해 사용할 수 있는 물리적 파일이 파일 시스템 내에 있는지를 확인한다. stat()이 ENOENT를 반환하면, 해당 경로에 파일이 존재하지 않는다는 것을 의미한다. 파일이 존재하지 않는 것을 확인한 후 프로세스는 다음 단계의 작업을 수행한다. 일반적으로 정적인 파일 기반의 레일스 시스템 캐싱(caching on Rails systems)은 이와 같이 동작한다. 요청에 해당(대응)하는 정적 파일이 존재하는지를 확인하고, 없다면 코드를 실행한다.
마지막으로 프로세스가 어떻게 동작하는지를 가볍게 흟어보자면, SQL 쿼리가 파일 디스크립터 16에 쓰였다는 것을 확인할 수 있다. lsof 출력 결과를 다시 보면, 파일 디스크립터 16은 또 다른 호스트의 postgresql 포트 (번호와 이름의 매핑은 /etc/services 파일에 설정되어 있음)로 연결된 TCP 연결이라는 것을 알 수 있다. sendto() 를 이용해 포맷된 SQL 쿼리를 postgresql 서버로 전송한다. 세번째 인자는 메시지의 길이이며, 네번째 인자는 플래그(flag) - 여기서는 MSG_NOSIGNAL - 인데 운영체제로 하여금 원격 연결 중에 오류가 발생하더라도 SIGPIPE 신호를 이용해 인터럽트(interrupt)하지 말 것을 요청하는 것이다.
프로세스는 다음으로 poll() 함수를 이용해 읽기를 준비하거나, 소켓 오류를 처리하거나, 데이터를 읽을 수 있으면 recvfrom()를 이용해 postgresql 서버의 응답을 받아들인다.
몇가지 세밀한 것들은 건너 뛰었지만, strace, lsof와 시스템 man 페이지를 조합해 프로그램의 보이지 않는 부분이 어떻게 동작하는지를 파악할 수 있다는 것을 이해했으리라 믿는다.
정상이란? (What’s “normal”?)
가끔은 프로세스의 개략적인(overview) 동작 방식만을 알고자 할 때도 있다. 90년대 후반에 "엔터프라이즈 자바"로 개발된 공급망관리시스템(supply chain management system) 제품의 장애를 해결할 때 이런 필요가 있었다. 잘 동작하다가도 특정 시간에 알 수 없는 상태에 빠지고 연결이 안되는 문제가 발생했었다. 우리는 소스 코드를 가지고 있지도 않았고, 기술지원 담당의 수준 낮은 답변에 지쳐 있었다. (결국 우리 스스로 모든 문제를 해결했다.) 그래서, 나는 "정상""적인 동작과 비정상적인 동작을 비교해보기로 결정했다.
주기적으로 프로세스의 시스템 호출 기록을 샘플링(sampling)한 후에 정상적인 샘플과 시스템 장애가 발생했을 때의 샘플을 비교해 보았다. 그 당시의 정확한 결과를 기억하지는 못하지만, 이전에는 쓰지 않았던 트릭(trick)을 사용해서 해결해냈다. 최근까지도 항상 strace를 동작시키는 스크립트를 작성하고, 결과를 기록하며, 집계를 생성하고는 하고 있으며, 문제를 해결하기 위해 strace 로그를 활용한다.
이제 유니콘 프로세스를 다시 살펴보자.
sudo strace -c -p 1346 Process 1346 attached - interrupt to quit ^CProcess 1346 detached % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 97.06 0.062667 29 2132 select 1.23 0.000791 0 7035 clock_gettime 1.19 0.000767 2 316 poll 0.42 0.000269 0 2116 2105 accept4 0.05 0.000030 0 137 write 0.04 0.000024 0 173 close 0.03 0.000017 0 2184 fcntl 0.00 0.000000 0 350 36 read 0.00 0.000000 0 79 open 0.00 0.000000 0 351 14 stat 0.00 0.000000 0 93 fstat 0.00 0.000000 0 79 mmap 0.00 0.000000 0 79 munmap 0.00 0.000000 0 3 rt_sigaction 0.00 0.000000 0 54 rt_sigprocmask 0.00 0.000000 0 156 ioctl 0.00 0.000000 0 2 alarm 0.00 0.000000 0 83 socket 0.00 0.000000 0 86 2 connect 0.00 0.000000 0 218 sendto 0.00 0.000000 0 195 10 recvfrom 0.00 0.000000 0 3 recvmsg 0.00 0.000000 0 11 shutdown 0.00 0.000000 0 1 bind 0.00 0.000000 0 5 getsockname 0.00 0.000000 0 1 getpeername 0.00 0.000000 0 1 getsockopt 0.00 0.000000 0 2 clone 0.00 0.000000 0 156 gettimeofday 0.00 0.000000 0 11 getrlimit 0.00 0.000000 0 2094 getppid 0.00 0.000000 0 12 futex 0.00 0.000000 0 196 ppoll ------ ----------- ----------- --------- --------- ---------------- 100.00 0.064565 18414 2167 total
strace 명령에 '-c' 옵션을 추가해 시스템 호출 횟수를 출력하도록 했다. '-c' 옵션을 사용해서 strace를 실행할 경우, 일정 시간만큼 실행하도록 한 후에, 프로세스에 인터럽트를 보내서 (ctrl-c) 집계 결과를 출력해야 한다. 출력 결과는 따로 설명이 필요없을 만큼 깔끔하다.
나는 지금 오전 7시에 글을 쓰고 있고, 시스템은 업무 시간 중에 가동된다. 따라서, 지금 추적하는 유니콘 프로세스는 거의 동작하지 않는 상태이다(inactive). 위에 출력된 추적 결과를 보았다면, 놀랄만한 데이터가 없다는 것을 알 수 있을 것이다. 유니콘은 대부분의 시간을 select() 호출에 사용한다. 우리는 이제 select() 를 이용해 들어오는 연결을 기다린다는 것을 안다. 그러니, 프로세스는 대부분의 시간을 클라이언트(브라우저)의 요청을 대기하는데 사용한다. 이건 말이 된다.
더불어 accept4() 의 에러 반환 값이 상대적으로 많다는 것을 볼 수 있다. 위에서 본 예제처럼, accept4() 는 일상적으로 EAGAIN 오류를 받고, 다시 연결을 기다리기 위해 select() 호출을 실행한다.
남은 함수 목록들은 C 시스템 호출들을 다시 공부하는데 도움이 될만한 좋은 예제이다. 할일 목록(to-do list)에 등록하고 하루에 하나씩 읽어보고 이해할 수 있도록 하는 것이 좋다. 이렇게 하면, 다음에는 유니콘 프로세스가 부하가 발생하거나 문제가 생겨서 분석할 때, 좀 더 수월하게 시스템 호출들을 분석할 수 있을 것이다.
어디가 느린거지? (Finding out what’s slow)
시스템의 성능 문제가 발생했을 때 - 시스템이 느려진 상태일 때 - strace를 어떻게 활용할 수 있는지에 대한 이야기로 마무리하고자 한다. 최근들어 업무에서 트롤 같은 문제(gremlin-like problems)가 간혹 발생한 적이 있어서 strace 를 이용해 원인을 추적한 적이 있는데, 분산 시스템 상에서 서로 관련이 없는 컴포넌트들의 성능이 저하되는 것으로 보이는데 이유를 알 수가 없었다. 데이터베이스 중에서 하나가 느려지고, 일부 웹 서비스의 성능이 저하되었다. 결국은 sudo 까지도 느려지고 말았다.
그것이 최종적인 단서였다. 우리는 sudo 명령을 strace로 추적했고, sudo 가 수행하는 각각의 시스템 호출 시간을 측정했다. 결국은 로그 명령문이 성능 저하의 원인이라는 것을 밝혀낸 것이다! 보아하나 syslog 서버를 제대로 확인하지 않고 잘못 설정해 놓았고, 그 서버로 로그를 전송하는 모든 서버가 이해할 수 없을만큼 느려지고 만 것이다.
간단한 예제를 이용해서 프로세스의 성능 문제를 추적해보도록 하자. 다음과 같은 C 소스로 작성된 프로그램을 떠올려보고, 왜 실행하는데 2초 이상의 시간이 소모 되는지를 밝혀내 보고자 한다.
#include <stdio.h> #include <unistd.h> void main() { printf("Hallo there!\n"); sleep(2); printf("Goodbye\n"); }
코드를 흟어보면, 눈에 띄는 명백한 문제는 없다 (헛!), 그러니 답을 찾기 위해 strace 를 실행할 것이다. '-t' 옵션을 추가해 추적을 하는 동안 각각의 시스템 호출이 수행되는데 걸리는 시간을 측정하도록 한다. 아래에 추적 결과를 보자:
$ strace -T ./time_me execve("./time_me", ["./time_me"], [/* 25 vars */]) = 0 <0.000307> brk(0) = 0x75f000 <0.000022> access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000027> mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3bb589a000 <0.000021> access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000021> open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 4 <0.000023> fstat(4, {st_mode=S_IFREG|0644, st_size=35614, ...}) = 0 <0.000019> mmap(NULL, 35614, PROT_READ, MAP_PRIVATE, 4, 0) = 0x7f3bb5891000 <0.000021> close(4) = 0 <0.000017> access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000021> open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 4 <0.000025> read(4, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\37\2\0\0\0\0\0"..., 832) = 832 <0.000020> fstat(4, {st_mode=S_IFREG|0755, st_size=1852120, ...}) = 0 <0.000019> mmap(NULL, 3966008, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0x7f3bb52b1000 <0.000022> mprotect(0x7f3bb5470000, 2093056, PROT_NONE) = 0 <0.000027> mmap(0x7f3bb566f000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x1be000) = 0x7f3bb566f000 <0.000027> mmap(0x7f3bb5675000, 17464, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3bb5675000 <0.000025> close(4) = 0 <0.000019> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3bb5890000 <0.000021> mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3bb588e000 <0.000021> arch_prctl(ARCH_SET_FS, 0x7f3bb588e740) = 0 <0.000018> mprotect(0x7f3bb566f000, 16384, PROT_READ) = 0 <0.002229> mprotect(0x600000, 4096, PROT_READ) = 0 <0.000027> mprotect(0x7f3bb589c000, 4096, PROT_READ) = 0 <0.000026> munmap(0x7f3bb5891000, 35614) = 0 <0.000036> fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 <0.000018> mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3bb5899000 <0.000021> write(1, "Hallo there!\n", 13Hallo there! ) = 13 <0.000035> rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000018> rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 <0.000019> rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000018> nanosleep({2, 0}, 0x7fffaa25c770) = 0 <2.000153> write(1, "Goodbye\n", 8Goodbye ) = 8 <0.000070> exit_group(8) = ?
보시다시피, strace 출력 결과의 모든 시스템 호출에 마지막 항목에 실행 시간(초 단위)이 포함되어 있다. 한줄 한줄 따라가 보면, 대부분의 호출 수행 시간이 매우 짧은데 마지막에서 2초 이상의 시간을 소모하는 호출을 찾을 수 있다! 미스터리는 풀렸다. 우리의 프로그램 코드 중에서 nanosleep() 함수를 호출하면서, 2초라는 인자를 넘기는 코드가 있는 것 같다.
실제로 추적할 때는 방대한 양의 추적 데이터를 파일에 저장한 후에 마지막 컬럼을 기준으로 정렬한 후, 문제가 되는 함수 호출부터 순서대로 확인하는 방식이 좋다.
남은 이야기 (There’s more!)
strace는 놀랍도록 많은 기능을 제공하는 툴(tool)이다. 그중에서 자주 사용하는 몇몇 옵션들만을 언급했을 뿐이며, 더 많은 옵션들이 있다. strace man 페이지를 찾아 더 많은 기능들을 살펴 보기 바란다. 그중에서 '-e' 옵션은 정규표현식을 입력받아 추적 결과를 필터링(filtering)하는 식으로 제어할 수 있기 때문에 꼭 살펴봐야 한다.
이 글을 끝까지 읽는 동안 언급된 모든 함수들의 의미를 이해하지 못했을 수도 있다. 그러나, 너무 걱정하지 말기 바란다. 나조차도 다 아는 것은 아니다. 대부분의 지식을 오동작하는 프로그램을 추적하면서 익히고, man 페이지를 읽으면서 공부했다. 만일 UNIX/LINUX 환경에서 개발하고 있다면, 개발하고 있는 프로그램을 strace로 추적해보기 바란다. 시스템 수준에 어떤 일이 벌어지는지를 학습해라. man 페이지를 읽어라. 탐험해라(Explore). 즐거울 뿐만 아니라, 이해하게 되고 이전보다 일도 잘하게 될 것이다.
추가 : 로터스 도미노 서버의 운명은? (UPDATE: And the fate of Lotus Domino server?)
듣자하니, 이 글이 도미노 서버를 설치하는 과정에서 발생한 드라마 같은 이야기로 알려지고 있는 것 같다. 트위터 같은 사이트에서 모든 사람들이 내게 "세상에나, 도미노 서버는 결국 어떻게 된거죠?" 라고 묻는다. 그러니, 이제 이야기의 끝자락을 마무리 하고자 한다.
어떻게든 시스템 호출을 추적하고 난 후에 도미노 서버를 고치고야 말았다. 유감스럽게도 그 당시에 정확히 어떻게 고쳐냈는지 기억하지 못하지만, 기적적으로 고쳐냈고 그 작업에 관련된 모든 사람들이 '엄청나게(huge)' 놀라워 했다는 것만은 확실하다.
나와 동료는 출장을 위해 빌렸던 빨간색 포트 무스탕 컨버터블에 타기 위해 주차장으로 갔고, 음악을 듣기 위해 사두었던 단 한장의 CD를 꽂고 볼륨을 높였다. (Guns & Roses’ Appetite for Destruction, 파괴하고픈 욕망) 차를 몰고 무사히 공항에 도착했지만, 우리는 CD를 잊고 차에 두고 내리고야 말았다. 무사히 아틀란타를 거쳐 멤피스에 도착한 후에야 CD를 놓고 왔다는 사실을 깨달아 버린 것이다.
누군가 우리 다음에 그 차를 빌린 사람은 우리만큼 글램 메탈(glam metal, hair metal) 음악을 즐겼기를 바란다.
- 상용 유닉스에서는 strace 명령이 아니라, truss 라는 명령을 사용해야 합니다.
- poor man's profiler 라는 글도 읽어보시면 좋습니다.
