안녕하세요, 넷마블 TPM실 기술분석팀 남태희입니다.
strace
strace는 리눅스에서 서버 병목을 확인할 수 있도록, 시스템 콜(시스템 호출, System call)을 측정하는 툴입니다. strace를 활용하면, 리눅스 커널과 프로세스 사이에서 발생하는 시스템 콜, 시그널 전달(Signal deliveries), 프로세스 상태 변화(Process state) 등을 모니터링할 수 있습니다.
strace에서 쓸 수 있는 여러 옵션은 strace 공식 페이지 또는 ‘-h’ 옵션에서 확인하실 수 있습니다.
strace: https://strace.io/
strace로 CentOS에서 아파치 웹서버 동작을 모니터링하는 출력 예시를 살펴보겠습니다.
$ strace -p 1502
Process 1502 attached
accept4(3, {sa_family=AF_INET, sin_port=htons(43396), sin_addr=inet_addr("000.000.000.000")}, [16], SOCK_CLOEXEC) = 8
getsockname(8, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("000.000.000.000")}, [16]) = 0
fcntl(8, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0
read(8, "GET / HTTP/1.1\r\nHost: 000.000.000.000"..., 8000) = 78
stat("/var/www/html/", {st_mode=S_IFDIR|0755, st_size=6, ...}) = 0
stat("/var/www/html/index.html", 0x7ffee1aa4750) = -1 ENOENT (No such file or directory)
lstat("/var", {st_mode=S_IFDIR|0755, st_size=278, ...}) = 0
lstat("/var/www", {st_mode=S_IFDIR|0755, st_size=33, ...}) = 0
lstat("/var/www/html", {st_mode=S_IFDIR|0755, st_size=6, ...}) = 0
lstat("/var/www/html/index.html", 0x7ffee1aa4750) = -1 ENOENT (No such file or directory)
write(2, "[Wed Feb 23 11:10:58.730871 2022"..., 255) = 255
stat("/usr/share/httpd/noindex/index.html", {st_mode=S_IFREG|0644, st_size=4897, ...}) = 0
open("/usr/share/httpd/noindex/index.html", O_RDONLY|O_CLOEXEC) = 9
setsockopt(8, SOL_TCP, TCP_CORK, [1], 4) = 0
writev(8, [{"HTTP/1.1 403 Forbidden\r\nDate: We"..., 252}], 1) = 252
sendfile(8, 9, [0], 4897) = 4897
setsockopt(8, SOL_TCP, TCP_CORK, [0], 4) = 0
write(6, "000.000.000.000 - - [23/Feb/2022:1"..., 91) = 91
times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 437663093
close(9) = 0
read(8, 0x7f077c509358, 8000) = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=8, events=POLLIN}], 1, 5000) = 1 ([{fd=8, revents=POLLIN}])
read(8, "", 8000) = 0
shutdown(8, SHUT_WR) = 0
poll([{fd=8, events=POLLIN}], 1, 2000) = 1 ([{fd=8, revents=POLLIN|POLLHUP}])
read(8, "", 512) = 0
close(8) = 0
read(4, 0x7ffee1aa4c0f, 1) = -1 EAGAIN (Resource temporarily unavailable)
accept4(3,
다른 옵션을 활용해 필터링을 추가하면 모니터링 항목을 좁힐 수도 있습니다.
$ strace -p 1502 -P /var/www/html
Process 1502 attached
lstat("/var/www/html", {st_mode=S_IFDIR|0755, st_size=6, ...}) = 0
lstat("/var/www/html", {st_mode=S_IFDIR|0755, st_size=6, ...}) = 0
하지만, 출력 예시를 보면 기본 설치된 strace는 커널의 시스템 콜만 출력하기 때문에, 응용 프로그램의 어느 액션으로 발생했는지 확인하기 어렵습니다. 이때 쓸 수 있는 옵션이 있습니다. ‘-k’입니다.
-k가 없다?
$ strace -k
strace: invalid option -- 'k'
Try 'strace -h' for more information.
strace 깃허브 릴리스 노트에서 볼 수 있듯이, strace는 꾸준히 기능 업데이트와 버그 수정을 이어오고 있습니다. ‘-k’ 옵션은 strace 5버전 릴리스에 맞춰 알파 기능으로 추가되고, 2019년 7월에 정식으로 공개된 기능입니다.
‘-k’ 옵션을 추가한 사연: frankpachot 미디엄
즉, 지금 쓰고 있는 strace에서 ‘-k’ 옵션이 동작하지 않는다면 최신 버전으로 재빌드를 해야 합니다.
strace 재빌드
strace 재빌드 환경은 CentOS 7 64비트 기준으로 설명하겠습니다. (우분투는 20.04 버전 이상이라면 ‘-k’ 옵션을 쓸 수 있는 strace 버전이 설치돼 있었습니다. 그렇지 않은 분이 계신다면, CentOS 기준을 참고하셔서 재빌드하시면 됩니다.)
먼저, strace 최신 버전에 필요한 의존성을 맞추기 위해 미리 설치해야 하는 패키지를 설치합니다. 특히, ‘unwind’ 라이브러리에 바이너리 의존성은 있으니, 원격지에서 실행한다면 원격지에도 ‘libunwind’를 설치해야 합니다. (‘libunwind’ 관련 라이브러리를 ‘/lib64/’ 디렉터리에 복사해 사용해도 동작합니다.)
$ yum install -y autoconf automake libunwind libunwind-devel gcc
의존성 패키지 설치를 마쳤다면, strace 깃허브 저장소에서 소스를 가져옵니다.
$ git clone https://github.com/strace/strace.git
이제, 받은 소스가 있는 디렉터리로 이동해서, 아래 옵션에 맞춰 빌드하면 됩니다. 빌드 결과물은 ‘/usr/local/bin’에 있으므로, strace 바이너리만 복사해서 사용해도 됩니다.
$ ./bootstrap
$ ./configure --with-libunwind
$ make
$ sudo make install
strace 재빌드 확인
strace에 ‘-k’ 옵션을 활성화하기 위한 재빌드였으므로, ‘-h’ 옵션을 실행해 ‘-k’ 옵션 설명을 볼 수 있다면 성공적으로 빌드를 마쳤다고 할 수 있습니다.
strace -k
이제 ‘-k’ 옵션으로 출력해보겠습니다.
$ strace -p 1502 -k
strace: Process 1502 attached
accept4(4, {sa_family=AF_INET6, sin6_port=htons(7236), inet_pton(AF_INET6, "::ffff:000.000.000.000", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [128->28], SOCK_CLOEXEC) = 9 > /usr/lib64/libc-2.17.so(accept4+0x17) [0xfff47]
> /usr/lib64/libapr-1.so.0.4.8(apr_socket_accept+0x49) [0x1e459]
> /usr/sbin/httpd(ap_unixd_accept+0x32) [0x5d762]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(child_main+0x51e) [0x377e]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(make_child+0x154) [0x3a34]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(startup_children+0x55) [0x3a95]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(prefork_run+0x9ef) [0x479f]
> /usr/sbin/httpd(ap_run_mpm+0x4d) [0x2634d] > /usr/sbin/httpd(main+0xa95) [0x1f0a5]
> /usr/lib64/libc-2.17.so(__libc_start_main+0xf4) [0x22554] > /usr/sbin/httpd(_start+0x28) [0x1f1de]getsockname(9, {sa_family=AF_INET6, sin6_port=htons(80), inet_pton(AF_INET6, "::ffff:000.000.000.000", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, [128->28]) = 0
> /usr/lib64/libc-2.17.so(getsockname+0x7) [0xff8b7]
> /usr/lib64/libapr-1.so.0.4.8(apr_socket_addr_get+0x6a) [0x1d2fa]
> /usr/sbin/httpd(core_create_conn+0xca) [0x318ca]
> /usr/sbin/httpd(ap_run_create_connection+0x72) [0x4b422]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(child_main+0x56b) [0x37cb]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(make_child+0x154) [0x3a34]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(startup_children+0x55) [0x3a95]
> /usr/lib64/httpd/modules/mod_mpm_prefork.so(prefork_run+0x9ef) [0x479f]
> /usr/sbin/httpd(ap_run_mpm+0x4d) [0x2634d] > /usr/sbin/httpd(main+0xa95) [0x1f0a5]
> /usr/lib64/libc-2.17.so(__libc_start_main+0xf4) [0x22554] > /usr/sbin/httpd(_start+0x28) [0x1f1de]fcntl(9, F_GETFL) = 0x2 (flags O_RDWR)
> /usr/lib64/libpthread-2.17.so(fcntl+0x44) [0xe8d4]
> /usr/lib64/libapr-1.so.0.4.8(sononblock+0x10) [0x1ec70]
> /usr/lib64/libapr-1.so.0.4.8(apr_socket_timeout_set+0x52) [0x1ed32]
이제 출력 결과물이 확실히 달라졌습니다. 단계별로 어느 응용 프로그램의 반응으로 나온 결과였는지 볼 수 있습니다. 아래는 strace에 ‘-k’ 옵션을 함께 사용해서 타임아웃(timeout) 위주 콜 스택을 보는 예시 명령어입니다.
$ strace -k -p 000 -x -i -T -Z
옵션 하나 추가해서 얻은 혜안
나침반 하나 들고 망망대해를 별자리만 바라보며 헤매고 다니다가, GPS 위성 신호와 정밀 지도를 얻은 기분이 이런 기분이라면 많이 과장된 표현일지도 모르겠습니다. 그래도 단 두 글자 추가만으로도 추적이 많이 편해졌으니, 충분히 효과를 볼 수 있지 않을까 합니다.
빠른 추적으로, 30분 이른 퇴근에 꼭 성공하시길 빌겠습니다.