5. 운영 로그로 APM 만들기: “느림”을 3분해해서 원인 좁히기

TechNote · NGINX · 05

로그로 성능/장애를 분해하기: request_time vs upstream_* 로 “느림”을 잡는 법

‘느림’이 NGINX인지 백엔드인지 감으로 때리지 않도록, 로그 필드로 시간을 분해하는 방법을 정리해 보겠습니다.

이 글의 목표
“느리다”를 감으로 잡지 않고, NGINX 로그 변수로
① 클라이언트 문제 / ② 프록시-업스트림 문제 / ③ 업스트림(앱) 문제
를 분리해 원인을 좁히는 루틴을 만듭니다.

1) 핵심 변수 6개

• $request_time: NGINX가 요청을 받아 “마지막 바이트를 클라이언트에 보낼 때까지” 걸린 총 시간
• $upstream_response_time: 업스트림이 응답하는데 걸린 시간(업스트림 지연)
• $upstream_connect_time: 업스트림에 TCP 연결 잡는 시간(네트워크/포트/혼잡)
• $upstream_header_time: 업스트림이 “첫 헤더”를 보낼 때까지 시간(앱 처리 지연 힌트)
• $upstream_addr / $upstream_status: 어느 업스트림이 응답했는지(분산/장애분석의 핵심)
• X-Request-ID: 요청 상관관계(포털/백엔드/로그를 한 줄로 연결)

2) 추천 log_format (운영자용 “APM 로그”)

# /etc/nginx/conf.d/10-log-format-apm.conf

log_format apm '$remote_addr [$time_local] '
               '"$request" $status '
               'rt=$request_time '
               'uct=$upstream_connect_time '
               'uht=$upstream_header_time '
               'urt=$upstream_response_time '
               'ua=$upstream_addr us=$upstream_status '
               'bytes=$bytes_sent '
               'rid="$http_x_request_id" '
               'ref="$http_referer" ua="$http_user_agent"';

access_log /var/log/nginx/access.log apm;

왜 이 구성이 좋나?
공식 NGINX도 “로깅으로 성능 모니터링”에서 타이밍 변수들을 APM처럼 쓰는 패턴을 소개합니다.

3) 해석법: “느림” 3분해(그림)

request_time vs upstream_* 시간 분해(개념도)

3분해로 원인 좁히기로그 한 줄의 rt/uct/uht/urt만 보고 “느림”을 3가지로 분류합니다.Case 1rt(총시간) ↑, urt(업스트림) 낮음rt ↑urt 낮음해석: 업스트림은 빨리 줬는데클라이언트로 “나가는 구간”이 느린 상태가능 원인• 클라이언트가 느리게 받음(다운로드/모바일/프록시)• 네트워크(클라↔프록시) 병목• 대용량 응답으로 전송 시간이 큼Case 2urt ↑ (보통 uct/uht도 ↑)urt ↑uct ↑uht ↑해석: 업스트림이 응답 자체가 느림즉 “앱/DB/서버 처리” 쪽 병목 가능성이 큼가능 원인• 앱 처리 지연 / DB 지연• 업스트림 서버 과부하 / 리소스 부족• 포트 혼잡 / 큐잉 증가Case 3uct ↑ (connect만 비정상)uct ↑urt/uht 정상해석: 업스트림 “접속”이 늦음연결 단계에서 지연이 발생(네트워크/방화벽/백로그)가능 원인• 네트워크 지연 / 라우팅 문제• 방화벽/NAT/프록시 경유 병목• 업스트림 포트 backlog/리스닝/연결 제한팁: “Case 분류 → 해당 구간(클라/프록시/업스트림)만 집중”하면 디버깅 시간이 급격히 줄어든다.

4) 실전 분석 커맨드(로그만으로도 충분히 강력)

4-1) 최근 200줄에서 “rt 상위 10개” 뽑기(초간단)

tail -n 20000 /var/log/nginx/access.log \
| awk 'match($0,/rt=([0-9.]+)/,a){print a[1],$0}' \
| sort -nr | head -n 10

4-2) 특정 경로(/api/)만 느린지 보기

grep '"/api/' /var/log/nginx/access.log \
| awk 'match($0,/rt=([0-9.]+)/,a){sum+=a[1];cnt++} END{print "avg_rt=",sum/cnt,"count=",cnt}'

4-3) 업스트림 서버별로 “누가 느린지” 분해(ua 기준)

awk '
match($0,/ua=([^ ]+)/,u) && match($0,/rt=([0-9.]+)/,a){
  key=u[1]; rt=a[1]; sum[key]+=rt; cnt[key]++
}
END{
  for(k in cnt) printf "%s\tavg_rt=%.4f\tcnt=%d\n", k, sum[k]/cnt[k], cnt[k]
}' /var/log/nginx/access.log | sort -k2 -nr | head

5) 주의사항(실무에서 꼭 만나는 것)

• upstream_* 값이 콤마(,)로 여러 개 나올 수 있음: 재시도/다중 업스트림을 거친 경우
• $request_time과 $upstream_response_time의 시간 기준 차이/정확도 차이 이슈가 존재할 수 있음(극단값 해석 주의)
• 로그를 APM처럼 쓰려면 Request-ID를 전 구간(브라우저→NGINX→Node→내부 API)에서 유지하는 게 핵심