앱은 0.049 초에 끝냈는데 사용자는 7 초를 기다렸다

한 줄 요약

앱은 0.049 초에 끝냈는데 사용자는 7 초를 기다렸다. 상태 코드는 200 이고, 애플리케이션 로그에도 이상이 없다. 이 종류의 장애는 오직 nginx 의 버퍼와 커넥션 설정에만 흔적을 남긴다.

왜 이게 필요했나

5xx 는 그래도 티가 난다. 대시보드가 빨개지고 알림이 울린다. 정말 오래 끄는 것은 아무도 잘못한 사람이 없어 보이는 장애다.

사용자는 "보고서 화면이 느리다" 고 한다. 개발팀은 앱 로그를 뒤져 "우리는 0.05 초에 응답했습니다" 라고 답한다. 인프라팀은 CPU·메모리·네트워크 그래프를 띄우고 "서버는 한가합니다" 라고 답한다. 둘 다 사실이다. 그리고 사용자도 사실을 말하고 있다. 이 회의는 결론 없이 끝나고, 다음 주에 똑같이 다시 열린다.

빠진 조각은 nginx 안에 있다. 응답이 디스크로 흘렀거나, 요청 본문이 임시 파일로 떨어졌거나, 매 요청마다 새 TCP 커넥션이 생기고 있다. 이 셋은 전부 상태 코드에 나타나지 않는다.

버퍼링 — 응답이 디스크로 새는 순간

proxy_buffering 은 기본이 on 이고, 그 이유는 좋다. nginx 가 업스트림의 응답을 최대한 빨리 다 받아 두고 업스트림 커넥션을 놓아 준 다음, 느린 클라이언트에게는 nginx 가 천천히 흘려 준다. 업스트림 스레드가 느린 사용자에게 붙들리지 않는다.

문제는 응답이 버퍼(proxy_buffer_size + proxy_buffers)보다 클 때다. 그때 nginx 는 남는 부분을 디스크의 임시 파일에 쓴다. 실측한 줄이다.

[warn] an upstream response is buffered to a temporary file  /var/lib/nginx/proxy/1/00/0000000001 while reading upstream,  request: "GET /app/big?n=8000000 HTTP/1.1"

여기서 두 가지를 눈여겨봐야 한다.

첫째, 수준이 [error] 가 아니라 [warn] 이다. 대부분의 팀은 error_log 를 error 수준으로 두거나, 알림을 [error] 문자열에만 건다. 그러면 이 줄은 영원히 아무에게도 도달하지 않는다. warn 수준으로 열어 두는 것이 이 장애를 볼 수 있는 유일한 방법이다.

둘째, 같은 요청의 액세스 로그는 200 이다. 상태 코드로는 절대 안 보인다.

같은 8MB 응답을 버퍼링을 켠 경로와 끈 경로로 각각 받아 재 본 숫자다.

proxy_buffering on   →  ut=0.049  rt=4.173   + [warn] 임시 파일proxy_buffering off  →  ut=3.188  rt=3.189   경고 없음

이 표가 버퍼링의 정체를 그대로 보여 준다. 켜면 업스트림은 0.049 초만 붙들리고 나머지는 nginx 가 떠안는다 — 대신 디스크로 샌다. 끄면 디스크로 새지 않는 대신 업스트림이 클라이언트가 다 받을 때까지 붙들린다. ut 가 rt 위로 올라붙는 것이 그 증거다.

그래서 판단은 이렇게 갈린다.

• 큰 파일·리포트 다운로드 → 버퍼링을 켜 둔다. 업스트림을 빨리 놓아 주는 값이 디스크 I/O 보다 크다. 대신 proxy_buffers 를 키워 임시 파일로 새는 양을 줄인다.
• SSE·롱폴링·실시간 로그 스트리밍 → 버퍼링을 끈다. 여기서는 업스트림이 오래 붙들리는 것이 정상이고, 오히려 버퍼링이 데이터를 뭉쳐 보내 실시간성을 해칠 수 있다.

다만 정직하게 적어 둔다. 이 실습 환경에서 1 초 간격으로 청크를 흘리는 스트리밍을 측정했을 때, proxy_buffering 을 켠 쪽과 끈 쪽 모두 청크가 1 초 간격으로 도착했다. nginx 는 클라이언트가 받을 수 있는 한 읽는 대로 흘려보낸다. "버퍼링을 켜면 스트리밍이 끊긴다" 는 흔한 설명은 적어도 이 조건에서는 재현되지 않았다. 스트리밍에서 버퍼링을 끄는 진짜 이유는 응답이 커졌을 때 디스크로 새지 않게 하려는 것과 업스트림 점유를 의도적으로 유지하려는 것에 가깝다.

본문 크기 — 앱이 영영 못 보는 413

client_max_body_size 기본값은 1m 이다. 이걸 넘는 업로드는 nginx 가 직접 413 으로 끊는다.

[error] client intended to send too large body: 3000000 bytes,  request: "POST /app/toobig HTTP/1.1"

같은 요청의 액세스 로그다.

413 ut=- rt=0.002 us=- "POST /app/toobig HTTP/1.1"

ut 와 us 가 둘 다 대시다. 업스트림에 간 적이 없다. 실습에서 업스트림 서버의 로그를 세어 보면 정말로 0 건이다. 개발팀이 "우리 로그에 그 요청이 없습니다" 라고 말할 때, 그건 발뺌이 아니라 정확한 사실이다.

본문 크기에는 두 번째 설정이 하나 더 붙어 있고 이쪽이 덜 알려져 있다. client_body_buffer_size(기본 16k, 플랫폼에 따라 8k)를 넘는 본문은 메모리가 아니라 디스크로 간다.

[warn] a client request body is buffered to a temporary file  /var/lib/nginx/body/0000000003, request: "POST /app/spill HTTP/1.1"

500KB 짜리 폼 업로드가 초당 수백 건 들어오는 시스템이라면 이 줄이 초당 수백 번 찍히고, 그만큼 디스크에 쓰고 지운다. 상태 코드는 전부 200 이다.

커넥션 재사용 — 세 줄이 모두 있어야 한다

업스트림 Keep-Alive 는 세 가지가 동시에 있어야 동작한다. 하나만 빠져도 조용히 꺼진다.

upstream app {  server 127.0.0.1:9101;  keepalive 16;                      # ①}location /app/ {  proxy_http_version 1.1;            # ②  proxy_set_header Connection "";    # ③  proxy_pass http://app/;}

같은 요청 10 건을 보내고 업스트림이 본 TCP 커넥션 수를 실측했다.

| 설정 | 업스트림이 본 커넥션 |
| --- | --- |
| 아무것도 없음 | 10 |
| ① 만 | 10 |
| ① + ② | 10 |
| ① + ② + ③ | 1 |

②만 넣고 끝내는 경우가 특히 많다. HTTP/1.1 로 올렸으니 됐겠거니 하는데, 클라이언트가 보낸 Connection 헤더가 그대로 업스트림에 전달되면서 매번 커넥션이 끊긴다. ③이 그 헤더를 지운다.

재사용이 안 되면 요청마다 새 소켓이 열리고 닫히면서 TIME_WAIT 이 쌓인다. 평소에는 아무 증상이 없다가 트래픽이 임계를 넘는 순간 포트 고갈로 한꺼번에 터진다. 그리고 그때 보이는 증상은 connect() failed — 즉 502 다. 원인은 커넥션 설정인데 증상은 "백엔드가 죽었다" 처럼 보인다. 증상과 원인이 다른 곳에 있는 이 코스의 주제가 여기서도 반복된다.

현장에서 만나는 모습

error_log 수준을 warn 으로 열어 둔다. 이 절에서 다룬 두 개의 임시 파일 경고는 전부 [warn] 이다. error 로 좁혀 두면 이 장애들은 존재하지 않는 것이 된다. 로그량이 걱정되면 수준을 좁힐 게 아니라 회전 주기를 줄인다.

로그 포맷에 $upstream_response_time 과 $request_time 을 함께 남긴다. 이 두 칸이 없으면 "앱이 느린가 전송이 느린가" 라는 첫 갈래를 나눌 수 없고, 그 갈래를 못 나누면 회의가 반복된다.

설정을 바꾸기 전에 재 본다. 버퍼를 키우는 것도 버퍼링을 끄는 것도 공짜가 아니다. 무엇을 얻고 무엇을 내주는지 숫자로 적어 두지 않으면, 6 개월 뒤에 아무도 그 값을 건드리지 못한다.

다음 실습에서 할 것

같은 8MB 응답을 버퍼링을 켠 경로와 끈 경로로 받아 두 숫자를 비교하고, 413 이 애플리케이션에 도달조차 하지 않는다는 것을 업스트림 로그로 증명하고, 커넥션 재사용을 3 종 세트 전후로 실측한다. 마지막에는 그 숫자들을 담은 운영 판단 기준서를 쓴다.