curl과 Nginx 시간을 어떻게 같은 요청에 놓을까¶

curl은 사용자가 기다린 바깥쪽 시간을, Nginx는 프록시 안쪽 시간을 봅니다. 두 자의 시작점을 맞춰 비어 있는 구간을 찾습니다.

예상 읽기 시간 6분 · 핵심 질문: 전체 350ms와 상위 서버 50ms 사이에는 무엇이 있는가

curl에서 전체 350ms, Nginx에서 상위 서버 응답 50ms가 나왔다고 하자. 남은 300ms를 모두 클라이언트 네트워크라고 부를 수는 없다. curl은 DNS 조회 전부터 응답 본문을 모두 받을 때까지 재고, Nginx는 클라이언트의 첫 요청 바이트를 읽은 뒤부터 기록한다. 그 사이에는 요청 업로드, Nginx 처리, 상위 연결 대기, 버퍼링과 느린 클라이언트로의 응답 전송이 있다.

두 도구를 함께 쓰는 핵심은 숫자를 바로 빼는 것이 아니라 각 값의 시작 사건과 종료 사건을 같은 시간선에 놓는 것이다.

sequenceDiagram
  participant C as curl 클라이언트
  participant N as Nginx 프록시
  participant A as 애플리케이션
  C->>N: DNS·TCP·TLS 뒤 HTTP 요청
  Note over C,N: curl은 요청 시작부터 누적 측정
  N->>A: 상위 연결을 얻어 요청 전달
  Note over N,A: Nginx는 연결·헤더·전체 응답을 별도 측정
  A-->>N: 응답 헤더와 본문
  N-->>C: 버퍼링 또는 스트리밍 전달
  Note over C,N: curl 전체 시간과 Nginx 요청 시간의 끝도 다를 수 있음

curl 값은 구간이 아니라 시작점부터의 누적 시간이다¶

time_namelookup은 DNS 완료까지, time_connect는 TCP 연결 완료까지, time_appconnect는 TLS 같은 애플리케이션 연결 완료까지다. time_starttransfer는 첫 응답 바이트까지, time_total은 본문을 모두 받을 때까지다.

따라서 TLS 자체 시간은 time_appconnect - time_connect, 첫 바이트 뒤 본문 전송은 time_total - time_starttransfer로 계산한다. 누적 값을 전부 더하면 DNS와 TCP 시간이 여러 번 들어간다.

curl --silent --show-error --output /dev/null \
  --write-out 'dns=%{time_namelookup}\nconnect=%{time_connect}\ntls=%{time_appconnect}\npretransfer=%{time_pretransfer}\nttfb=%{time_starttransfer}\ntotal=%{time_total}\nconnects=%{num_connects}\nremote=%{remote_ip}\nhttp=%{http_version}\nbytes=%{size_download}\n' \
  https://api.example.com/health

num_connects, 원격 IP, HTTP 버전과 응답 바이트도 같이 남긴다. 같은 주소처럼 보여도 다른 CDN 거점에 연결됐거나, 한 요청은 새 연결이고 다른 요청은 재사용 연결일 수 있다. curl을 실행할 때마다 프로세스를 새로 시작하면 이전 프로세스의 연결 풀을 재사용할 수 없다는 점도 주의한다.

Nginx 값은 클라이언트 구간과 상위 서버 구간을 나눈다¶

$request_time은 Nginx가 클라이언트의 첫 요청 바이트를 읽기 시작한 때부터 접근 로그를 쓰는 때까지다. 요청 본문을 받는 시간, Nginx 처리, 상위 서버, 응답을 클라이언트에 쓰는 시간이 함께 들어갈 수 있다.

$upstream_connect_time은 선택한 상위 서버와 연결하는 데 걸린 시간이다. 상위 구간에도 TLS가 있으면 그 협상을 포함한다. $upstream_header_time은 상위 서버에서 응답 헤더를 받을 때까지, $upstream_response_time은 상위 응답 전체를 받을 때까지다.

log_format timing escape=json
  '{"request_id":"$request_id",'
  '"status":$status,'
  '"request_time":$request_time,'
  '"upstream_addr":"$upstream_addr",'
  '"upstream_status":"$upstream_status",'
  '"upstream_connect_time":"$upstream_connect_time",'
  '"upstream_header_time":"$upstream_header_time",'
  '"upstream_response_time":"$upstream_response_time",'
  '"request_length":$request_length,'
  '"bytes_sent":$bytes_sent}';

상위 서버 연결 실패나 시간 초과 뒤 재시도하면 변수에 여러 값이 쉼표나 콜론으로 기록될 수 있다. 마지막 값만 숫자로 변환해 저장하면 앞선 실패와 재시도가 사라진다. 상위 주소·상태와 원래 값의 순서를 함께 보존해야 사용자가 기다린 전체 과정을 복원할 수 있다.

요청 식별자로 두 시간선을 포갠다¶

클라이언트가 요청 식별자를 헤더에 넣고, Nginx가 그대로 상위 서버에 전달하며 접근 로그에도 남긴다. 애플리케이션도 같은 식별자로 작업 대기, 업무 처리와 의존 서비스 시간을 기록한다. 같은 식별자가 없으면 비슷한 시각의 서로 다른 요청을 비교할 수 있다.

그다음 바깥에서 안쪽으로 읽는다.

curl의 total과 ttfb 차이가 크면 응답 크기와 다운로드·버퍼링을 확인한다.
curl의 TTFB에 비해 Nginx $request_time이 작으면 DNS·연결·요청 업로드와 클라이언트 경로를 확인한다.
Nginx $request_time에 비해 $upstream_response_time이 작으면 프록시 대기·버퍼링·클라이언트 전송을 확인한다.
상위 서버 시간에 비해 애플리케이션 업무 로그가 작으면 런타임 대기·필터·직렬화를 확인한다.

각 빼기 값은 하나의 원인이 아니라 다음에 쪼개야 할 범위다. 예를 들어 $request_time - $upstream_response_time에는 순수 네트워크만이 아니라 요청 본문 수신과 Nginx 자체 처리도 들어간다.

숫자 조합에서 읽을 수 있는 신호¶

상위 헤더 시간은 큰데 상위 전체 응답 시간과 차이가 작다면 애플리케이션이 첫 결과를 만드는 데 대부분의 시간을 썼을 가능성이 크다. 헤더는 빠른데 전체 응답이 늦다면 상위 서버의 스트리밍·큰 본문·느린 생성 경로를 본다.

Nginx는 상위 응답을 빨리 받았는데 $request_time이 길다면 느린 클라이언트로의 전송, 응답 버퍼링, 큰 본문을 의심한다. 요청 본문이 큰 업로드라면 Nginx가 상위 서버로 넘기기 전에 전체를 받는 설정 때문에 상위 시간에는 보이지 않는 대기가 생길 수 있다.

curl의 첫 호출만 DNS·연결·TLS가 크고 이후 작다면 연결 재사용이 정상적으로 이득을 주는 상황일 수 있다. 반복 호출에서도 새 연결 수가 계속 1이라면 클라이언트 풀, 프록시의 유휴 시간 제한과 Connection 헤더를 확인한다.

비교 결과는 조건과 함께 남긴다¶

좋은 기록은 “Nginx가 느렸다”로 끝나지 않는다. 다음처럼 같은 요청, 측정 경계와 다음 확인 지점이 드러나야 한다.

요청 8f3…의 curl 전체 시간은 0.352초, 최초 바이트는 0.301초였다. Nginx 전체 요청은 0.247초이고 두 번의 상위 서버 시도는 0.151초 실패와 0.052초 성공으로 남았다. 차이는 단순 클라이언트 네트워크가 아니라 프록시 재시도가 포함된 결과다. 상위 연결 시간 제한과 멱등성 정책을 먼저 확인한다.

첫 연결과 재사용 연결, 작은 응답과 실제 응답, 오류 없는 요청과 재시도 요청을 섞지 않는다. 변경 뒤에는 p50뿐 아니라 p95·p99와 오류율도 함께 비교한다. 타이밍 로그가 민감한 경로나 헤더 값을 포함하지 않도록 하고, 운영 저장 비용이 크면 모든 요청에는 핵심 값만 남기고 느린 요청의 상세 정보를 선택적으로 보존한다.