APM Trace, 로그, JVM 지표를 하나의 증거로 묶기

AI 장애 분석 포스트모템 시리즈 4/9

metric query가 열린 뒤 Old Gen부터 다시 봤습니다. 가장 먼저 확인한 건 요청량이었습니다.

시간대	요청량
baseline	9~16 RPS
13:30 KST 전후	약 70 RPS
13:40 KST 전후	약 103 RPS

GET /v3/auth가 6~10배 늘어 있었습니다. 이때 top resource는 압도적으로 GET /v3/auth였고, /heartbeat는 background health probe에 가까웠습니다.

Datadog indexed span 기준으로 GET /v3/auth 요청이 증가했고, 같은 시간대에 Old Gen은 상승했지만 major collection time은 0에 가까웠습니다.

Old Gen 증가는 그 안에서 다시 의심하기로 했습니다.

trace metric family를 확인하는 자리

먼저 trace.servlet.request.* 계열을 조회하려 했습니다. 그런데 값이 비어 있었습니다. 이 서비스는 Spring MVC servlet 기반이 아니라 Spring WebFlux/Reactor Netty 기반이었습니다.

정확한 metric family는 이쪽이었습니다.

trace.netty.request.*

프레임워크를 잘못 가정하면 metric이 비어 있거나 엉뚱한 결론이 나옵니다.

Old Gen은 실제로 증가했습니다

Old Gen 증가 자체는 착시가 아니었습니다. 특정 task/AZ 그룹에서 Old Gen은 대략 이렇게 움직였습니다.

145 MB baseline
-> 320 MB peak
-> 이후 task rotation 후 하락

처음 스크린샷이 보여준 현상은 실제였습니다. 다만 관측된 현상이라는 것과 원인이라는 것은 다른 이야기였습니다.

GC는 원인이 아니었습니다

Old Gen이 증가했으면 다음 질문은 GC였습니다. 그래서 확인한 항목은 아래와 같았습니다.

major GC count
major GC time
minor GC count
minor GC time
heap max
process CPU
thread count

결과는 명확했습니다.

major GC count = 0
major GC time = 0
minor GC overhead = 낮음
heap 사용률 = max 대비 약 15%
CPU = 병목 아님
thread count = 안정적

Full GC나 major GC pause가 event loop를 멈춘 상황은 아니었습니다. 따라서 Old Gen 증가는 원인이 아니라 결과 쪽으로 다시 정렬됐습니다.

Old Gen 증가는 stuck request retention의 신호였습니다

가장 설득력 있는 설명은 stuck request retention이었습니다. 요청이 오래 살아 있으면 다음 객체들이 같이 살아남습니다.

• request context
• headers
• cookies
• JWT claims
• coroutine continuation
• tracing context
• response buffer

짧은 요청이라면 young generation에서 사라질 객체들이 오래 살아남으면 minor GC를 몇 번 지나 Old Gen으로 승격될 수 있습니다. 그래서 Old Gen 증가는 이렇게 해석하는 편이 맞았습니다.

Old Gen 증가
= stuck request가 많았다는 증거
!= GC가 장애를 만들었다는 증거

CPU와 thread도 원인이 아니었습니다

JVM process CPU는 낮았고 thread count도 안정적이었습니다. 다만 한 cold-start task가 순간적으로 높은 CPU를 보였지만, 장애 시작 후 replacement task가 갑자기 traffic을 받은 결과로 보는 쪽이 더 자연스러웠습니다. 처음 slowness를 만든 원인으로 보기는 어려웠습니다.

Fargate에서는 host가 비어 있을 수 있습니다

/api/v1/hosts는 권한 보완 후 200이 됐습니다. 그런데 결과는 비어 있었습니다. 이건 실패가 아니었습니다.

서비스가 Fargate task로 떠 있어서 Datadog host inventory에 일반 host처럼 보이지 않았습니다. 따라서 이 경우 host가 아니라 task tag를 봐야 했습니다. 예를 들면:

task_arn
ecs_task_arn
ecs_service
availability_zone

API가 200을 돌려도 실행 환경에 따라 해석이 달라집니다.

세 계층을 같이 볼 때 유효했던 순서

이번 조사에서 유효했던 순서는 아래와 같았습니다.

1. APM span search로 느린 resource를 찾습니다.
2. log search로 exception과 cancellation을 확인합니다.
3. event search로 ECS/Watchdog/deploy event를 붙입니다.
4. trace metric으로 request count와 top resource를 봅니다.
5. JVM metric으로 heap/GC/CPU/thread를 검증합니다.
6. infra metric으로 task/AZ 분포를 봅니다.

APM만 보면 no child span을 잘못 해석할 수 있습니다. 로그만 보면 cancellation을 원인으로 착각할 수 있습니다. JVM 그래프만 보면 Old Gen을 원인으로 오해할 수 있습니다.

세 가지를 같이 봐야 했습니다.

재분류 결과

재조사 전 heap/GC는 possible contributor로 두고 있었습니다. 하지만 재조사 후에는 symptom으로 내려갔습니다. 더 강한 설명은 아래 흐름이었습니다.

GET /v3/auth traffic surge
-> long-lived suspended requests
-> Old Gen retention
-> heartbeat timeout observed

뒤의 코드 분석에서 이 suspended request의 더 구체적인 원인은 R2DBC pool acquire wait로 좁혀집니다.

원인, 증상, 증폭 요인을 나누기

Old Gen 증가는 중요한 단서였지만 원인은 아니었습니다. metric 권한을 보완해 GC, heap max, CPU, thread count를 확인하자 stuck request의 결과로 재분류됐습니다. 분석에서 필요한 일은 단서를 버리는 게 아니라 어느 범주에 속하는지 다시 나누는 일이었습니다.

원인인가?
증상인가?
증폭 요인인가?
상관관계만 있는 지표인가?

이 네 가지를 구분해야 그래프가 설명이 되고, 설명이 되어야 RCA에 남길 수 있었습니다. 이 기준을 가지고 다음 편에서는 이 재분류를 AWS 원천 지표로 다시 검증한 흐름을 정리합니다.