도와줘! strace

배경

Nginx upstream_response_time이 간헐적으로 10초씩 튀는 현상이 발생했습니다.

nginx -t도 정상, 어플리케이션 APM 로그도 정상(159ms), 그런데 클라이언트는 timeout. 어디서 10초가 사라지는 건지 로그만 봐서는 알 수 없었습니다.

결론부터 말하면 원인은 DNS였습니다 — 정확히는, API 서버가 들어온 요청의 IP로 PTR 레코드 역방향 조회를 시도하고, 외부 DNS 서버가 응답하지 않아 5초씩 타임아웃을 반복한 것이었습니다.

이 글은 그 트러블슈팅 과정과, 처음 써본 strace가 어떻게 결정적 단서를 줬는지, 그리고 strace 사용법을 함께 정리한 것입니다.

1. 증상 파악

Nginx 로그

upstream_response_time이 10초 발생하는 것을 확인했습니다.

upstream_response_time: 10.xxx

특정 시간대(2024.03.13 18:35:32 ~ 18:35:59)에 response_time이 집중적으로 높았고, 동시간대에 서버에 올라가 있는 특정 어플리케이션에서만 발생했습니다.

패킷 덤프 분석

해당 시간대 패킷을 확인해보니 흐름은 이랬습니다.

nginx → 서버#2  POST Request 전송
서버#2 → nginx  ACK 즉시 수신 (패킷은 받음)
서버#2 → nginx  약 10초 후 200 OK Response

서버는 요청을 받았고, ACK도 즉시 보냈습니다. 그런데 응답은 10초 뒤에 나왔습니다.

APM 로그

APM에는 총 처리시간 477ms, 어플리케이션 처리시간 159ms로 기록되어 있었습니다. 어플리케이션 입장에서는 정상적으로 빠르게 처리했다고 보고하고 있었습니다.

클라이언트는 10초 이상 걸려 timeout → 재시도 → 서버는 이미 처리 완료 상태이므로 500 error 응답하는 상황이었습니다.

2. 로그 교차 분석

여기서 핵심 질문이 생겼습니다.

왜 Nginx가 기록한 request 시간과 어플리케이션에 찍힌 request 시간이 다른가?

실제 어플리케이션 로그를 확인해보니

13:43:51.497  패킷 수신 (Nginx → 서버 전달)
13:43:56.531  어플리케이션 Incoming request 처리 시작

5초의 공백이 있었습니다. 패킷은 받았는데, 어플리케이션이 요청을 처리하기 시작하기까지 5초가 걸렸습니다.

이 5초 동안 서버가 무엇을 하고 있었는지를 알아야 했습니다. Nginx 문제도, 어플리케이션 로직 문제도 아닌 그 사이 어딘가에 원인이 있었습니다.

3. 원인 추적 — strace

시스템 콜 수준에서 어플리케이션이 실제로 무엇을 하고 있는지 확인하기 위해 strace를 사용했습니다.

strace -p <PID> -tt -T 2>&1 | grep -E "poll|send|connect|DNS"

strace 출력 분석

10109 16:27:30 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 113
...
# /etc/hosts 에서 찾지 못하자 외부 DNS 질의 시작
10109 16:27:30 connect(113, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.8.8")}, 16) = 0
10109 16:27:30 sendto(113, "PTR 쿼리 데이터...", 44, ...) = 44
10109 16:27:30 poll([{fd=113, events=POLLIN}], 1, 5000)  # 8.8.8.8 에 PTR 쿼리, 5초 대기
10109 16:27:35   = 0 (Timeout)                           # 응답 없음, 타임아웃

10109 16:27:35 connect(50, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("8.8.4.4")}, 16) = 0
10109 16:27:35 sendto(50, "PTR 쿼리 데이터...", 44, ...) = 44
10109 16:27:35 poll([{fd=50, events=POLLIN}], 1, 5000)   # 8.8.4.4 로 재시도, 5초 대기
10109 16:27:40   = 0 (Timeout)                           # 또 응답 없음

10109 16:27:40 sendto(113, ...) = 44                     # 8.8.8.8 다시 재시도
10109 16:27:45   = 0 (Timeout)
...
10109 16:27:50 close(113)                                # 20초 만에 포기
10109 16:27:50 close(50)

해석

1. 어플리케이션이 요청을 받은 뒤 PTR 레코드 조회를 시도하고 있었습니다.

sendto에 담긴 DNS 쿼리 페이로드를 디코딩하면 192.168.77.xxx.in-addr.arpa — 클라이언트 IP에 대한 역방향 DNS 조회(PTR lookup)입니다.

2. 외부 DNS(8.8.8.8, 8.8.4.4)가 응답하지 않아 5초씩 타임아웃이 반복됐습니다.

기본 DNS 타임아웃이 5초이고, 두 DNS 서버 모두 응답이 없어 8.8.8.8 → 8.8.4.4 → 8.8.8.8 ... 순서로 재시도하면서 총 수십 초가 소비된 것입니다.

PTR 쿼리 (8.8.8.8)  → 5초 타임아웃
PTR 쿼리 (8.8.4.4)  → 5초 타임아웃
PTR 쿼리 (8.8.8.8)  → 5초 타임아웃
...

poll 시스템 콜의 타임아웃 파라미터가 5000(5000ms)으로 설정된 것도 확인됩니다.

4. 원인과 해결

직접 원인

어플리케이션 소스코드에 들어온 요청의 클라이언트 IP로 hostname을 조회하는 코드가 있었습니다. 이 코드가 PTR 레코드 역방향 조회를 일으킨 것이었습니다.

→ 어플리케이션 코드에서 DNS 조회 부분을 제거하여 해결했습니다.

2차 원인

서버들의 DNS 설정이 외부 DNS(8.8.8.8, 8.8.4.4)로 되어 있었고, 내부 IP에 대한 PTR 레코드를 외부 DNS가 알 리 없으니 응답이 없었던 것입니다.

임시 해결책

코드 수정 전까지 /etc/hosts에 직접 등록하여 DNS 조회를 우회했습니다.

# /etc/hosts
192.168.77.35  api.internal.example.com

/etc/hosts에 항목이 있으면 DNS 조회를 건너뛰므로 즉시 효과가 있었습니다.

근본 해결

1. 어플리케이션 코드의 DNS 역방향 조회 코드 제거
2. (추후) 서버 DNS 설정을 외부 DNS → 내부 DNS로 변경

5. strace란

프로세스가 실행되는 동안 커널에 요청하는 시스템 콜(system call) 을 추적하는 도구입니다.

어플리케이션은 파일 열기, 네트워크 연결, 프로세스 생성 같은 작업을 직접 하지 않습니다. 커널에 요청(시스템 콜)을 보내고, 커널이 대신 처리합니다. strace는 이 요청과 응답을 그대로 보여줍니다.

어플리케이션
    ↓  시스템 콜 요청 (open, read, connect, ...)
   커널
    ↓  처리 결과 반환
어플리케이션

strace는 ptrace 커널 인터페이스를 사용해 프로세스에 붙고 각 시스템 콜의 진입과 반환을 가로챕니다.

어떤 상황에서 쓰는가

로그에 없는 지연 구간이 있을 때
어플리케이션이 어떤 파일을 열고 있는지 확인할 때
네트워크 연결 흐름을 추적할 때
권한 오류(EACCES, EPERM)의 원인을 찾을 때
프로세스가 왜 느린지 시스템 콜 수준에서 확인할 때

6. 기본 사용법

새 프로세스 실행하면서 추적

strace <명령어>

# 예시
strace hostname -f
strace ls /etc

실행 중인 프로세스에 붙기

strace -p <PID>

PID를 모를 때:

strace -p $(pidof nginx)
strace -p $(pgrep -n java)

Ctrl+C로 추적을 중단합니다. 프로세스는 계속 실행됩니다.

7. 주요 옵션

타임스탬프

# 절대시각 (HH:MM:SS.usec)
strace -p <PID> -tt

# 상대시각 (이전 syscall로부터 경과 시간)
strace -p <PID> -r

각 syscall 소요 시간

strace -p <PID> -T

출력 끝에 <0.000123> 형태로 해당 syscall에 걸린 시간(초)이 추가됩니다.

syscall 필터링

# 네트워크 관련만
strace -p <PID> -e trace=network

# 파일 관련만
strace -p <PID> -e trace=file

# 특정 syscall만
strace -p <PID> -e trace=openat,read,write,connect

# 시그널만
strace -p <PID> -e trace=signal

자주 쓰는 카테고리입니다.

카테고리포함	syscall
file	open, openat, read, write, close, stat, ...
network	socket, connect, bind, sendto, recvfrom, ...
process	fork, execve, clone, wait, exit, ...
signal	kill, sigaction, pause, ...
ipc	pipe, mq_open, shmget, ...

문자열 길이

기본값 32자로 잘립니다. 긴 경로나 데이터를 보려면 늘려야 합니다.

strace -p <PID> -s 65535

출력을 파일로 저장

# 타임스탬프 + 소요시간 + 파일 저장
strace -p <PID> -tt -T -s 65535 -o strace.log

자식 프로세스까지 추적

strace -p <PID> -f

멀티스레드, 멀티프로세스 어플리케이션(Nginx worker, Java 스레드 등)에서 필수입니다.

통계 요약

strace -p <PID> -c

어떤 syscall이 몇 번 호출됐고 얼마나 걸렸는지 요약표를 출력합니다.

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- --------
 53.21    0.001234         123        10         2 poll
 30.12    0.000700          70        10           sendto
 ...

8. 출력 읽는 법

기본 형식

[PID]  [시각]  syscall(인자, ...) = 반환값 <소요시간>

10109 16:27:30 openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 113 <0.000021>
10109 16:27:30 read(113, "127.0.0.1\tlocalhost\n...", 4096)        = 1305 <0.000008>
10109 16:27:30 close(113)                                          = 0 <0.000003>

반환값 해석

반환값	의미
양수	성공. 파일 디스크립터 번호, 읽은 바이트 수 등
= 0	성공 (void 성격의 syscall)
= -1 ENOENT	실패 — 파일/경로 없음
= -1 EACCES	실패 — 권한 없음
= -1 ETIMEDOUT	실패 — 연결 시간 초과
= -1 ECONNREFUSED	실패 — 연결 거부
= 0 (Timeout)	poll/select 타임아웃 만료

블로킹 syscall

블로킹 중에 다른 스레드로 스위치되면 출력이 두 줄로 나뉩니다.

10109 16:27:30 poll([{fd=113, events=POLLIN}], 1, 5000 <unfinished ...>
# ... 다른 스레드 출력 ...
10109 16:27:35 <... poll resumed>)   = 0 (Timeout)

<unfinished ...> — syscall 진입, 아직 반환 안 됨
<... resumed> — 이전에 중단된 syscall이 반환됨

두 줄의 시각 차이가 해당 syscall에서 블로킹된 시간입니다.

파일 디스크립터 추적

openat의 반환값이 이후 read, write, close에서 첫 번째 인자로 나옵니다.

openat(..., "/etc/resolv.conf", ...) = 5     # fd=5 로 열림
read(5, "nameserver 8.8.8.8\n...", 4096)    # fd=5 읽기
close(5)                                     # fd=5 닫기

9. 실전 패턴

어떤 파일을 열고 있는지 확인

설정 파일 경로가 불확실하거나, 예상치 못한 파일을 열고 있는지 확인할 때 씁니다.

strace -p <PID> -e trace=openat,open -s 256 2>&1 | grep -v "= -1"

= -1은 실패한 open이므로 필터링하면 실제로 열린 파일만 봅니다.

네트워크 연결 흐름 추적

strace -p <PID> -e trace=network -tt -s 256

어디로 connect하고, 무엇을 보내고 받는지 확인할 수 있습니다.

DNS 역방향 조회 탐지

응답 지연의 원인이 DNS인지 의심될 때:

strace -p <PID> -tt -T -e trace=network 2>&1 | grep -E "connect|sendto|poll"

in-addr.arpa가 포함된 sendto가 보이고 뒤이어 poll ... Timeout이 반복되면 PTR 역방향 조회 타임아웃입니다.

# 이런 패턴이 반복되면 DNS PTR lookup 타임아웃
sendto(113, "...192.7in-addr.arpa...", 44, ...) = 44
poll([{fd=113, events=POLLIN}], 1, 5000)
  = 0 (Timeout)

권한 오류 원인 파악

SELinux나 파일 권한 문제를 확인할 때:

strace -p <PID> -e trace=file 2>&1 | grep "EACCES\|EPERM"

느린 syscall 찾기

어떤 syscall이 오래 걸리는지 통계로 확인합니다.

strace -p <PID> -c -f
# Ctrl+C 로 중단하면 통계 출력

출력량이 너무 많을 때

실행 중인 서버 프로세스는 syscall이 엄청나게 많습니다. 파일로 저장한 뒤 분석합니다.

# 저장
strace -p <PID> -tt -T -f -s 256 -o /tmp/strace.log

# 분석 — 오래 걸린 것만
grep -E "<[0-9]+\.[0-9]{2,}>" /tmp/strace.log | sort -t'<' -k2 -rn | head -20

# 분석 — 실패한 것만
grep "= -1" /tmp/strace.log

10. 주의사항

오버헤드

strace는 모든 syscall을 인터셉트하므로 운영 중인 서버에 붙으면 성능이 크게 떨어집니다. 짧게 실행하고 파일로 저장 후 분석하는 방식이 안전합니다.

# 10초만 추적하고 종료
timeout 10 strace -p <PID> -tt -T -o /tmp/strace.log

-f 옵션과 PID 혼재

멀티스레드 어플리케이션에서 -f를 쓰면 PID가 섞여서 출력됩니다. 특정 스레드만 보려면 grep으로 필터링합니다.

grep "^10109" /tmp/strace.log

문자열 기본값 32자 제한

경로나 데이터가 잘려 보이면 -s 65535를 추가합니다. 기본값 32자는 실제 분석에서 너무 짧습니다.

11. 배운 것

로그의 공백을 발견하면 시스템 콜을 보자

어플리케이션 로그와 Nginx 로그 사이에 5초 공백이 있었는데, 이 공백은 어떤 로그에도 찍히지 않았습니다. 어플리케이션 코드에서 처리가 시작되기 전에 일어난 일이기 때문입니다.

strace는 어플리케이션이 OS에 요청하는 모든 시스템 콜을 보여줍니다. 로그로 설명이 안 되는 지연이 있다면 시스템 콜 수준에서 확인하는 것이 효과적입니다.

PTR 레코드 역방향 조회가 성능에 미치는 영향

어플리케이션이 클라이언트 hostname을 알기 위해 getaddrinfo()나 gethostbyaddr() 같은 함수를 호출하면 내부적으로 PTR 레코드 조회가 발생합니다. 해당 IP의 PTR 레코드가 없거나 DNS 서버가 응답하지 않으면 타임아웃(기본 5초)이 발생하고, 이것이 요청 처리 전체를 블로킹합니다.

내부 IP에 대한 PTR 조회를 외부 DNS로 보내면 응답이 오지 않아 타임아웃이 필연적으로 발생합니다.

nginx -t 통과, APM 정상 → 그래도 문제는 있다

이 케이스처럼 어플리케이션 관점에서는 정상으로 보여도 OS 레벨에서 블로킹이 발생할 수 있습니다. 트러블슈팅 시 단일 레이어의 로그만 믿지 말고 레이어 간 시각 차이를 먼저 파악하는 것이 중요합니다.

Nginx 로그 시각 ≠ 어플리케이션 로그 시각
→ 그 사이 공백에 OS 레벨 동작이 숨어 있다

마치며

strace를 처음 보면 출력이 압도적입니다. 하지만 읽는 포인트는 세 가지입니다.

어떤 syscall인가 — open이면 파일, connect면 네트워크
반환값이 무엇인가 — 양수면 성공, -1 E...면 실패
얼마나 걸렸는가 — -T로 소요시간 확인, 블로킹 syscall은 resumed 줄 시각 차이로 계산

"로그에 없는 시간"이 보이면 strace를 먼저 떠올리면 됩니다.

명령어 정리

# 실행 중 프로세스에 붙기
strace -p <PID>

# 타임스탬프 + 소요시간 + 문자열 전체
strace -p <PID> -tt -T -s 65535

# 파일 접근만
strace -p <PID> -e trace=file -s 256

# 네트워크만
strace -p <PID> -e trace=network

# 자식 포함 + 파일 저장
strace -p <PID> -f -tt -T -s 256 -o strace.log

# syscall 통계 요약
strace -p <PID> -c

# 10초 후 자동 종료
timeout 10 strace -p <PID> -tt -T -o strace.log

참고

'system' 카테고리의 다른 글

HAProxy 클라이언트 IP 보존 — Transparent Proxy와 Proxy Protocol (0)	2026.06.04
리눅스 격리 기술 - cgroup, namespace, union mount (0)	2026.06.04
인프라 모니터링: 무엇을, 왜, 어떻게 볼 것인가 (0)	2026.06.04
시스템 성능 분석: CPU, 메모리, 디스크, 네트워크 (0)	2026.06.04
스토리지 종류와 구성 방식 정리 (0)	2026.06.04

배경