느린 게 우리 탓인가 외부 탓인가 — 다중 홉 요청의 지연을 홉별로 분해하기

총 응답 시간만으로는 조사할 곳을 정하기 어려웠다

내가 맡은 중계 구간은 게이트웨이, 내부 서버, 외부 제공자 API를 차례로 거쳤다. 응답은 역순으로 돌아왔다. 게이트웨이는 요청마다 총 처리 시간을 기록했지만, 그 숫자만으로는 어느 구간에서 오래 걸렸는지 알기 어려웠다. 나는 계층별 로그를 요청번호로 연결하는 SQL을 작성해 지연 구간을 확인했다.

전체 응답이 3초 걸려도 내부 처리에 대부분을 썼는지, 외부 응답을 기다렸는지에 따라 다음 조사가 달라진다. 응답이 더 늦어지면 게이트웨이의 읽기 타임아웃으로 요청이 실패하기도 했다. 총 응답 시간에 더해 내부 서버와 외부 호출의 소요 시간을 함께 볼 필요가 있었다.

이미 남기던 로그를 요청번호로 연결했다

각 계층에는 요청과 응답 시각이 남아 있었다. 기록은 서로 다른 테이블에 흩어져 있었지만 같은 요청번호를 공유했다. 나는 이 번호를 상관 ID로 삼아 한 요청의 기록을 모았다. 외부 구간도 우리 쪽에서 기록한 호출 시작과 응답 수신 시각으로 확인했다.

여기서 중요한 것은 기록 사이의 관계를 복원할 수 있느냐다. 같은 ID를 전달하면 조인이 단순해지지만, 계층별 ID가 달라도 부모 요청과 자식 요청의 대응 관계가 남아 있으면 연결할 수 있다. 반대로 시간대가 비슷하다는 이유만으로 로그를 묶으면 동시 요청을 혼동할 수 있다.

이 작업은 기존 로그를 이용한 요청 추적이었다. OpenTelemetry처럼 작업 단위인 스팬(span)과 부모·자식 관계를 명시적으로 수집하는 체계를 도입한 것은 아니다. 요청번호가 같아도 재시도와 병렬 호출을 구별할 정보가 없으면 세부 호출 관계까지 복원하기 어렵다. OpenTelemetry 추적 API

계층별 시간은 서로 겹친다

계산 전에 측정 구간부터 구분해야 한다. 외부 응답을 동기적으로 기다리는 구조에서는 내부 서버의 소요 시간에 외부 호출 시간이 포함된다. 게이트웨이의 총 시간에는 두 구간이 모두 들어간다.

다음은 실제 측정값이 아닌 설명용 예시다. 외부 호출이 한 번이고 재시도나 병렬 처리가 없으며, 시각은 같은 기준으로 맞췄다고 가정했다. 단위는 밀리초(ms)다.

세 소요 시간을 더하면 중복 계산이 된다. 이 예시에서는 내부 서버가 외부 호출 전에 쓴 시간이 50ms, 응답을 받은 뒤 쓴 시간이 50ms다. 두 시간을 합친 100ms와 외부 호출 2,800ms가 내부 서버의 2,900ms를 이룬다. 이 100ms도 순수한 CPU 실행 시간은 아니며 다른 대기가 포함될 수 있다.

따라서 다음 계층의 요청 시각에서 이전 계층의 응답 시각을 빼면 계층 간 대기 시간을 구할 수 없다. 위 예시에서 내부 서버의 요청 시각 50에서 게이트웨이의 응답 시각 3,000을 빼면 −2,950ms가 나온다. 하위 호출이 끝나야 상위 요청이 끝나는 구조를 거꾸로 계산한 결과다.

서로 다른 서버의 시각을 뺄 때는 시계 오차도 고려해야 한다. 시간대를 통일해도 서버 시계가 동기화되는 것은 아니다. 작은 차이를 곧바로 네트워크나 큐 대기로 해석하지 않아야 한다. Jaeger도 이런 시계 오차가 추적 시각에 미치는 영향을 별도로 다룬다. Jaeger 시계 오차 설명

조인할 때는 측정 경계와 로그 누락을 함께 본다

아래 SQL은 당시 운영 코드를 옮긴 것이 아니라 핵심 방식을 PostgreSQL 16 문법으로 재구성한 예제다. 세 테이블은 요청번호당 최대 한 행이며, 시작·종료 시각은 timestamptz 형식이라고 가정했다. 게이트웨이 테이블에는 미완료 요청도 남고, 아직 기록되지 않은 종료 시각은 NULL이다.

app_log는 내부 요청 전체를, ext_log는 같은 내부 서버에서 외부 호출을 감싼 구간을 기록한다. 위 표처럼 외부 응답을 받은 뒤 내부 요청이 완료되는 구조를 전제로, 외부 호출 전후의 시간은 같은 서버의 시각끼리 계산한다. 타임스탬프 차이는 구간(interval)이므로 초로 추출한 뒤 1,000을 곱해 밀리초로 바꿨다. PostgreSQL 날짜·시간 연산

SELECT
    g.req_no,
    1000 * EXTRACT(EPOCH FROM (g.done_at - g.recv_at))
        AS gateway_total_ms,
    1000 * EXTRACT(EPOCH FROM (a.done_at - a.recv_at))
        AS app_total_ms,
    1000 * EXTRACT(EPOCH FROM (e.end_at - e.start_at))
        AS external_call_ms,
    1000 * EXTRACT(EPOCH FROM (e.start_at - a.recv_at))
        AS app_before_call_ms,
    1000 * EXTRACT(EPOCH FROM (a.done_at - e.end_at))
        AS app_after_call_ms
FROM gw_log g
LEFT JOIN app_log a ON a.req_no = g.req_no
LEFT JOIN ext_log e ON e.req_no = g.req_no
ORDER BY external_call_ms DESC NULLS LAST;

요청번호당 한 행이라는 전제는 실제 로그에 적용하기 전에 확인해야 한다. 재시도나 여러 외부 호출로 행이 늘어나면 요청번호만으로 조인한 결과도 중복될 수 있다. 이때는 호출·시도 식별자로 관계를 구분해야 한다. 병렬 호출의 소요 시간을 단순히 합쳐 전체 시간에서 빼는 방식도 맞지 않는다. 계산값이 음수라면 0으로 보정하기보다 시계 변경, 잘못 연결된 로그, 측정 경계의 불일치를 먼저 확인해야 한다.

LEFT JOIN은 대응하는 하위 로그가 없어도 게이트웨이 요청을 남긴다. 다만 NULL만으로 요청이 어느 계층에서 멈췄는지 확정할 수는 없다. 실제 미도달 외에도 로그 수집 누락·지연이나 키 불일치가 가능하다. 완료되지 않은 요청의 시간을 0으로 채우지 않고 오류·타임아웃 기록과 함께 확인해야 한다. 완료 요청의 지연 통계를 낼 때도 미완료·누락 건수는 따로 봐야 한다.

이중화된 게이트웨이는 노드별 평균도 비교했다. 이는 특정 노드에 지연이 몰렸는지 살피기 위한 분류였다. 같은 방식을 다시 적용한다면 API와 시간대를 맞추고 요청 수, 지연의 상위 백분위수, 오류율도 함께 확인할 것이다. 노드마다 처리하는 요청의 구성이 다르면 평균 차이만으로 노드 자체의 문제라고 판단하기 어렵다.

외부 호출 구간으로 조사 범위를 좁혔다

당시 로그를 연결해 보니 지연의 대부분이 외부 호출 구간에 있었다. 내가 만든 쿼리의 성과는 전체 응답 시간에 묻혀 있던 이 구간을 찾아낸 것이다. 내부 코드의 어느 부분이든 막연히 의심하는 대신, 시간이 오래 걸린 외부 API와 요청을 구체적으로 확인할 수 있었다.

다만 우리 쪽에서 잰 외부 호출 시간은 외부 서버 내부의 처리 시간과 같지 않다. 네트워크 왕복 시간이 포함되고, 기록 위치에 따라 연결 확보나 클라이언트 내부 대기도 포함될 수 있다. 따라서 이 결과만으로 외부 제공자의 내부 코드가 원인이라고 확정할 수는 없다. 호출 경계와 연결 상태를 확인하고 상대 측 로그와 대조할 범위를 좁힌 근거로 보는 것이 맞다.

운영에서는 응답이 느린 일부 API의 타임아웃을 늘리는 대응도 했다. 이는 늦게 오는 응답을 더 기다리도록 한 조정이며 외부 API를 빠르게 만든 것은 아니다. 이런 조정은 상위 요청의 제한 시간과 더 오래 점유되는 연결·작업 스레드의 여유를 함께 검토해야 한다.

학습

• 총 시간과 포함된 구간을 구분해야 한다. 내부 서버의 요청 처리 시간에는 외부 호출 대기가 들어갈 수 있다. 조인에 앞서 각 시각을 어디에서 남기는지 확인해야 계산 결과를 해석할 수 있다.
• 기존 로그도 조사 범위를 좁히는 근거가 된다. 내가 추가한 것은 흩어진 기록을 연결하는 쿼리였다. 같은 요청을 식별할 수 있었기에 지연이 집중된 구간을 찾을 수 있었다.
• 관측한 구간과 원인 확정은 구분해야 한다. 외부 호출이 오래 걸렸다는 사실은 다음 조사의 출발점이다. 내부 처리, 전송, 연결 대기를 더 나누려면 그 경계를 관측할 추가 기록이 필요하다.