분산 추적으로 WAS 병목 찾기 — trace 따라 장애 좁히는 실무 절차

span 트리를 읽는 법 — 자기 시간(self time) vs 하위 호출 대기

span 트리를 읽을 때 가장 흔히 하는 실수는 span duration 을 그대로 병목의 원인으로 오해하는 것이다. duration 은 자식 span 의 시간을 포함한 총 시간이므로, 실제 WAS 코드가 소비한 시간(self time)과 구별해야 한다.

그림 2. 한 요청을 구간별로 갈라 보면 범인이 드러난다 — 총 820ms 중 DB 가 570ms.

self time 계산은 간단해 보이지만, 실제 span 트리가 깊어질수록 주의가 필요하다. 자식 span 이 여러 개일 때, 모든 자식 span 의 duration 을 합쳐야 한다. 병렬로 실행되는 자식 span 들의 경우, 각 span 의 duration 이 겹칠 수 있으므로 단순히 합산하면 실제 WAS 시간이 왜곡될 수 있다. 대부분의 APM 도구(OPENMARU APM 포함)는 span tree를 시각화할 때 자식 span 의 겹치는 시간을 차감한 self time을 함께 표시한다.

self time이 긴 span 은 WAS 내부에 병목이 있음을 의미한다. 반대로 self time이 짧고 자식 span duration이 긴 span 은 외부 시스템(DB, 캐시, 외부 API)에 병목이 있다.

WAS 병목의 전형 5종과 span 서명

WAS 병목은 크게 다섯 가지 유형으로 분류할 수 있다. 각 유형은 span에 고유한 서명(signature)을 남기며, 이 서명을 식별하는 것이 장애 분석의 첫걸음이다.

그림 3. 장애의 80%는 WAS·애플리케이션 계층에서 난다 — 그 안의 단골 다섯이 이것이다.

1. 스레드 풀 고갈

모든 요청 span이 동일한 서버 span에서 대기 시간이 증가한다. span duration이 급증하지만 자식 span은 없다. span attributes에 thread_pool_active_threads가 pool_max에 근접한 값을 보인다. Span Kind는 Server다.

스레드 풀 고갈의 특징은 모든 요청이 동시에 영향을 받는다는 점이다. 단일 요청의 trace만 보면 “갑자기 왜?”라고 생각할 수 있지만, 여러 trace를 비교하면 공통점이 보인다. 모두 동일한 WAS 인스턴스의 span에서 대기 시간이 길어진다.

오판 포인트: 스레드 풀 고갈은 span duration이 길어지지만, 그 원인이 네트워크 지연이나 DB 응답이 아니라는 점이다. 자식 span이 짧으면서도 부모 span의 duration이 긴 경우, WAS 내부에서 스레드가 풀을 기다리고 있을 가능성이 크다.

2. 커넥션 풀 대기

데이터베이스 또는 외부 API 호출 span(긴 duration을 가진 하위 span)이 부모 span 내에서 대기한다. span attributes에 db.system 또는 http.url이 존재하고, span duration의 대부분이 실제 쿼리 실행이 아닌 커넥션 획득 대기 시간이다.

커넥션 풀 대기의 핵심 서명은 “span duration은 길지만, 실제 DB query span(sub-span)은 매우 짧다”는 점이다. 커넥션 풀에서 커넥션을 얻기까지 대기하는 시간이 span duration에 포함되지만, 실제 쿼리 실행 자체는 순식간에 끝난다.

오판 포인트: span duration이 길다고 해서 항상 네트워크 지연이라고 착각할 수 있다. 커넥션 풀 대기에서는 span의 start-to-end가 길지만, 실제 db query span(sub-span)은 매우 짧다. 이 차이를 구별하려면 DB span의 self time을 확인해야 한다.

3. GC Pause

span 자체에는 직접 나타나지 않는다. span duration이 불규칙하게 튀는 현상으로 감지된다. GC Pause 동안 WAS 스레드가 멈추므로 span이 진행되지 않는다. span tree에서 특정 span이 예상보다 훨씬 오래 걸릴 때 GC Pause를 의심한다.

GC Pause의 가장 큰 특징은 span에 직접적인 흔적이 없다는 점이다. GC가 발생하면 JVM 전체 스레드가 멈추므로, 그 순간 진행 중이던 span의 duration이 비정상적으로 길어진다. 하지만 그 span의 attributes에는 GC 관련 정보가 없으므로, span만으로 GC Pause를 확인하는 것은 불가능하다.

오판 포인트: GC Pause는 span 이벤트로 직접 기록되지 않으므로, span duration의 이상 증가만 보고 외부 API 지연으로 오인하기 쉽다. GC Pause를 확인하려면 해당 시간대의 GC 관련 메트릭(JVM heap 사용량, GC 횟수, GC pause time)을 반드시 함께 봐야 한다.

4. 외부 API 지연

outgoing HTTP span(Client SpanKind)이 긴 duration을 보인다. span attributes에 http.method, http.url, http.status_code가 있고, span duration이 외부 서비스 응답 시간과 일치한다.

외부 API 지연의 특징은 span attributes에 외부 서비스의 URL이 명시되어 있다는 점이다. Client span의 http.url을 보면 어느 외부 서비스인지 즉시 파악할 수 있다.

오판 포인트: 외부 API span이 길지만 WAS 내부에서 그 원인을 알 수 없다. 외부 서비스의 문제가 span에만 반영될 뿐, WAS 측에서 원인 파악이 불가능하다. 이 경우 WAS 코드 수정으로 해결할 수 없는 문제이며, 외부 서비스 측에 장애 조치를 요청하거나 타임아웃/회로 브레이커 설정으로 대응해야 한다.

5. N+1 쿼리

단일 HTTP 요청 span 아래에 동일한 패턴의 DB span이 반복적으로 나타난다. 예를 들어 ‘GET /users’ span 아래에 100개의 ‘SELECT * FROM orders WHERE user_id=?’ span이 병렬 또는 순차적으로 생성된다. span의 attributes에 db.statement이 유사하고 parent_span_id가 동일하다.

N+1 쿼리의 서명은 “구조”다. 개별 DB span의 duration은 각각 짧으므로, 전체 span duration이 크지 않으면 N+1을 발견하기 어렵다. span tree의 구조를 살펴봐야 한다. 동일한 패턴의 DB span이 수십~수백 개가 동일한 parent span 아래에 반복되면 N+1 쿼리다.

오판 포인트: 개별 DB span은 각각 짧으므로, 전체 span duration이 크지 않으면 N+1을 발견하기 어렵다. span tree의 구조를 살펴봐야 하며, DB span의 수를 세는 것이 중요하다.

OPENMARU APM은 span tree 시각화에서 동일한 패턴의 span이 반복되는 경우 이를 자동으로 감지해 경고한다.

trace_id로 메트릭·로그로 건너뛰어 원인을 확정하는 순서

span은 병목의 ‘위치’만 알려준다. ‘원인’을 확인하려면 trace_id를 사용해 메트릭과 로그 시스템으로 건너뛰어야 한다. 이 과정은 다음과 같은 순서로 진행한다.

그림 4. 세 축을 잇는 것은 3단계 Correlate 다 — 여기서 trace_id 가 접착제로 쓰인다.

1단계: span에서 병목 위치를 식별한다.

먼저 span tree를 읽어서 self time이 긴 span, 또는 자식 span duration이 긴 span을 찾는다. 앞서 설명한 5종의 서명을 대조해 병목 유형을 좁힌다.

2단계: trace_id로 해당 시간대의 메트릭을 조회한다.

해당 span이 발생한 호스트·컨테이너의 CPU, 메모리, GC 메트릭을 trace 시간 창에서 조회한다. Prometheus나 Grafana에서 span의 service_name과 trace_id가 겹치는 시간대를 필터링하면, 해당 시점의 시스템 상태를 확인할 수 있다.

스레드 풀 고갈이 의심되면 해당 시간대의 WAS 스레드 풀 사용량 메트릭을 확인한다. 커넥션 풀 대기가 의심되면 커넥션 풀 활성·유휴 카운트를 확인한다. GC Pause가 의심되면 JVM heap 사용량과 GC 횟수·pause time 메트릭을 확인한다.

3단계: trace_id로 해당 서비스의 로그를 필터링한다.

해당 span의 service_name과 trace_id로 로그 시스템을 필터링한다. Elasticsearch나 LOKI에서 trace_id를 검색하면 해당 요청과 관련된 모든 로그를 한눈에 볼 수 있다.

DB span이 의심되면 slow query log를 확인한다. WAS span이 의심되면 GC 로그, 스레드 덤프, 커넥션 풀 로그를 확인한다. 외부 API 지연이 의심되면 WAS의 HTTP 클라이언트 로그를 확인해 응답 코드와 지연 시간을 확인한다.

4단계: 메트릭과 로그의 교차 검증으로 원인을 확정한다.

메트릭과 로그에서 span에서 추정한 병목 유형과 일치하는 증거를 찾는다. 만약 span에서는 외부 API 지연으로 보였지만, 메트릭에서는 WAS의 CPU가 정상이고 GC도 정상이라면, 실제로는 외부 서비스의 문제일 가능성이 높다. 반대로 span에서는 별다른 이상이 없어 보였지만 메트릭에서 GC pause가 빈번했다면, GC Pause가 병목이었을 가능성이 크다.

이 교차 검증 과정이 분산 추적의 진정한 가치다. span만으로 결론 내리지 않고, 메트릭과 로그로 원인을 확정하는 것이 올바른 장애 분석 절차다.

샘플링 때문에 정작 느린 요청이 안 잡히는 문제

분산 추적 시스템을 도입하고 나서도 여전히 장애 분석이 안 되는 경우가 있다. 그 이유는 샘플링이다.

head sampling은 trace가 시작될 때 확률로 샘플링한다. 1% sampling을 사용하면 100개 요청 중 1개만 trace를 남기고, 나머지 99개는 완전히 무시된다. 빠르고 간단하지만, ‘느린 요청’이나 ‘에러가 있는 요청’을 놓칠 수 있다. 특히 1초 이상 걸리는 요청이 sampling 밖으로 빠지면 장애 분석이 불가능해진다.

tail sampling은 trace가 끝난 후에 ‘지연 시간이 임계값을 넘었는가’, ‘에러가 있었는가’ 등을 기준으로 샘플링한다. 느린 요청을 놓치지 않지만, 구현이 복잡하고 Collector에 stateful tail sampling processor가 필요하며, 높은 트래픽에서 메모리·CPU 부하가 크다.

head sampling을 쓰고 있는데 tail sampling으로 넘어가야 하는 판단 기준은 세 가지다.

첫째, 느린 요청 trace가 아예 없다. 대시보드에서 1초 이상 걸리는 요청이 한 건도 trace로 남지 않는다면, sampling 확률이 너무 낮다는 뜻이다.

둘째, sporadic한 지연이 trace에 전혀 포착되지 않는다. 가끔씩 발생하는 지연이 trace에 전혀 나타나지 않아, “왜 가끔씩 느려질까”라는 질문을 답하지 못하는 경우다.

셋째, APM 대시보드에서 ‘sampled avg latency’와 ‘실제 avg latency’ 차이가 10배 이상 나는 경우. sampled latency는 샘플링된 요청의 평균 지연 시간이고, 실제 avg latency는 전체 요청의 평균 지연 시간이다. 이 차이가 크다는 것은 샘플링된 요청이 전체 분포를 대표하지 못한다는 뜻이다.

tail sampling으로 넘어가면 느린 요청과 에러가 있는 요청은 반드시 trace로 남게 된다. 다만 Collector의 부하가 증가하므로, 샘플링 임계값을 적절히 설정하고 자주 발생하는 패턴(예: 200 OK + 100ms 미만)은 샘플링에서 제외하는 등의 최적화가 필요하다.

MSA 환경에서 trace가 제공하는 추가 가치

MSA 환경에서는 trace의 가치가 더 커진다. 하나의 HTTP 요청이 수십 개의 서비스를 거치므로, trace 없이 각 서비스의 로그만 보면 ‘어느 서비스에서 문제가 시작되었는지’를 연결할 수 없다.

MSA에서 흔한 패턴 중 하나가 cascade failure(연쇄 장애)다. 한 서비스의 지연이 상위 서비스의 span duration에 연쇄적으로 반영된다. trace를 보면 지연의 시작점을 찾을 수 있지만, ‘누가 먼저 느려졌는지’를 span의 start_time만으로 판단하면 오류일 수 있다. 네트워크 레이턴시가 span duration에 포함되므로, 실제 서비스 지연과 네트워크 지연을 분리해야 한다.

또 다른 패턴이 fan-out이다. 하나의 요청이 여러 하위 서비스로 병렬 분기한다. trace 상에서 여러 Client span이 동일한 parent span 아래에서 병렬로 실행된다. fan-out이 많을수록 parent span duration은 longest(child)에 가까워지므로, 개별 span duration이 짧아도 전체 요청은 느릴 수 있다.

MSA에서 trace_id로 문제 확산을 추적할 때는 span attributes에 service.name, deployment.environment 등을 기록해, 특정 버전·환경에서만 발생하는 병목을 trace 수준에서 필터링할 수 있다.

FAQ

Q. span duration이 길다고 해서 항상 병목인가요?

아닙니다. span duration은 자식 span의 시간을 포함한 총 시간이므로, 자식 span이 정상적으로 오래 걸린 것일 수 있습니다. 병목 여부를 판단하려면 self time을 확인해야 합니다. self time이 길 때만 WAS 내부에 병목이 있습니다.

Q. GC Pause를 span만으로 확인할 수 있나요?

확인할 수 없습니다. GC Pause는 span에 직접적인 흔적을 남기지 않습니다. span duration이 불규칙하게 튀는 현상으로 의심할 수 있지만, 반드시 JVM GC 관련 메트릭(heap 사용량, GC 횟수, pause time)을 교차 검증해야 합니다.

Q. head sampling과 tail sampling 중 무엇을 써야 하나요?

트래픽이 적고 지연이 드문 환경에서는 head sampling으로 충분합니다. 지연이 빈번하거나 느린 요청이 장애로 이어지는 환경에서는 tail sampling이 필요합니다. head sampling을 쓰고 있는데 느린 요청 trace가 아예 없거나, sampled latency와 실제 latency 차이가 10배 이상 나면 tail sampling으로 넘어가는 시점입니다.

Q. trace_id가 없으면 로그에서 특정 요청을 추적할 수 없나요?

trace_id가 없으면 로그만으로는 특정 요청의 전체 경로를 재구성하기 어렵습니다. 각 서비스의 로그를 시간순으로 나열해볼 수는 있지만, 여러 서비스를 거치는 MSA 환경에서는 정확한 연결고리를 만들기 힘듭니다. trace_id는 분산 추적의 핵심 식별자로, 메트릭·로그·trace를 연결하는 접착제입니다.

Q. N+1 쿼리는 span에서 어떻게 발견하나요?

단일 HTTP 요청 span 아래에 동일한 패턴의 DB span이 반복적으로 나타나는지 구조를 살펴봐야 합니다. 개별 DB span의 duration은 각각 짧으므로, 전체 span duration이 크지 않아도 N+1일 수 있습니다. DB span의 수를 세고, parent_span_id가 동일한지, db.statement이 유사한지 확인하면 N+1 쿼리를 발견할 수 있습니다.

문의

OPENMARU Observability 는 분산 추적·메트릭·로그를 한 화면에서 잇습니다. span 트리 시각화와 trace_id 기반 교차 조회로 WAS 장애의 원인 구간을 좁힙니다.

• OPENMARU Observability — 분산 추적·메트릭·로그 통합 제품 소개
• WEB/WAS 모니터링 — WAS 구간을 span 단위로 보는 기능
• 도입 문의·견적 — PoC·도입 상담