갑자기 모든 Gateway에서 500이 발생했던 이유
배경
오후 12:40 분 경, 운영 환경의 Gateway 세 개가 동시에 많은 에러가 발생했습니다. 인터널, 유저향, 외부 파트너(Open) 까지 세 서비스 모두 500과 502가 같이 폭증했어요.
세 서비스가 같은 시점에 같이 발생했다는 건 경험상 보통 두 가지 중 하나였어요. 첫째는 공통 의존 대상에 문제가 생겼을 때, 둘째는 트래픽 자체가 spike 쳤을 때. 이 글은 그 진짜 원인을 찾아 들어가는 과정과, 표면 증상 뒤에 어떤 메커니즘이 숨어 있었는지에 대한 기록을 남겨두고자 합니다.
문제
먼저 1시간치 에러 스팬 수를 서비스 별로 잡았는데요. 한쪽 Gateway가 전체의 94%를 차지했고, 나머지 둘도 평소 대비 비정상적으로 많았습니다.
분 단위로 시간 분포를 보면 12:39~12:40 약 2분간 폭증한 게 명확하게 보였어요. 평소 분당 요청 량으로 봤을 때 약 12배 이상으로 한 번 튀고 다시 200대로 돌아왔거든요. 즉 burst 자체는 짧았지만, 그 시점에 뭔가 클러스터 전반을 흔든 게 있었던 것이라 생각했습니다.
에러 메시지 패턴은 두 종류로 나뉘었습니다. 유저 앱 쪽에서는 다운스트림 서비스가 400 예외를 반환했고, 외부 파트너 Gateway 쪽에서는 상품 서비스에 대한 ReadTimeoutException이 찍혔습니다. 여기서 흥미로운 건 timeout이 정확히 5초였다는 점이고, Gateway가 외부로는 502 Bad Gateway를 던지고 있었어요.
1차 가설: 다운스트림이 죽었나?
자연스러운 첫 가설은 "다운스트림 API가 죽어서 Gateway가 5초 timeout 뜨고 502 던지는 것"이었습니다. 하지만 트레이스를 까보니 그게 아니었습니다.
외부 파트너 Gateway의 502 응답 한 건을 골라서 데이터독의 트레이스 콜체인을 따라가봤더니, 외부 파트너 쪽은 5,005ms에 502를 응답했지만 다운스트림 상품 서비스 자체는 status:ok로 5,002ms에 200을 응답하고 있었어요. 즉 서비스 들은 살아있는데 응답이 그냥 늦었던 거고, Gateway의 read timeout 5초를 넘긴 거였죠.
5초의 대부분은 상품 서비스 안의 MongoDB 호출에 가있었습니다. 그리고 관측 도구로 살펴보니, 그 안에서 가장 많이 시간을 잡아먹은 게 MongoDB의 createIndexes 명령이었어요.
2차 가설: createIndexes가 X lock을 잡았나?
이 시점에서 처음 떠올린 메커니즘은 다음과 같았는데요.
"여러 서비스가 hot path에서 createIndexes를 호출하는 잘못된 패턴이 있고, 그게 컬렉션 락을 잡아서 다른 쿼리들이 대기하나?"
createIndexes는 인덱스를 만드는 명령인데, 보통은 빈이 등록되는 시점 또는 마이그레이션 스크립트 등으로 1회성으로 돌리는 게 정석입니다. 그런데 저희 팀이 만들고있는 제품 특성 상 멀티 테넌시 형태를 제어하기 위해 런타임 시점에 테넌트 별 테이블이 생성되기때문에 멱등을 제공해주는 인덱스 생성 API를 매 요청마다 전달하는 형태로 설게되어있어요.
근데 이번 이슈로 파보니, 잘못 제어하면 요청 처리 경로 안에서 이걸 호출하고 있다면, 동일 컬렉션의 다른 read/write가 락 큐에 묶일 수 있었어요.
MongoDB의 락 모델을 짚고 가면, 일반 read는 IS(Intent Shared), 일반 write는 IX(Intent Exclusive), DDL 작업(createIndexes 같은 것)은 X(Exclusive) 락을 잡습니다.
IS와 IX는 서로 공존 가능해서 동시 read/write가 막히지 않지만, X 락은 다른 모든 락과 충돌하기 때문에 잡힌 동안 그 컬렉션의 모든 작업이 줄을 서야 합니다.
실제로 같은 burst 시간대를 다시 까보니 상품 서비스뿐 아니라 내원객 서비스, 예약 서비스, 결제 서비스 등이 동시에 createIndexes를 요청하고 있었습니다. 각 서비스가 자기 컬렉션에 수십 개씩 인덱스를 한꺼번에 만들어대고 있었거든요.
만약, 정말 이게 원인이라면 깔끔한 그림이 그려집니다. 동시 createIndexes burst가 X 락 큐를 만들고, 모든 쿼리가 그 큐에서 대기하면서 5초 timeout을 깨는 거죠. 인덱스가 hot path에서 도는 패턴만 고치면 끝나는 문제일 수 있고요.
가설이 흔들리는 순간
그런데 검증 과정에서 첫번 째 가설이 잘못된 것을 확인했습니다.
"이미 만들어진 index여도 createIndexes가 X lock을 잡나?" 멱등하다했는데..?
확인해보니, 제가 알고 있던 락 그림이 정확하지 않았습니다.
찾아보니 MongoDB 4.2부터 Hybrid Index Build가 기본인데요. 빌드 중에는 collection-level X 락을 잡지 않습니다. 시작/종료 시점에 아주 짧게(보통 1ms 이하) X 락을 잡고, 빌드 중에는 IX 락만 유지해서 같은 컬렉션의 read/write가 동시에 가능합니다. 게다가 이미 동일 spec의 인덱스가 존재하면 사실상 no-op이라 의미 있는 락도 안 잡고요.
이걸 인정하고 나면 createIndexes가 직접적인 spark였다는 가설은 흔들립니다. 그 burst 시점에 새 인덱스를 실제로 빌드하고 있었다면 모를까, 대부분의 createIndexes 호출은 no-op이었을 가능성이 높거든요.
즉 burst 시점의 createIndexes가 3초 걸린 건 원인이 아니라 결과였습니다. 다른 무언가가 클러스터를 묶고 있어서, no-op이어야 할 명령조차 응답을 못 받고 있던 거죠.
진짜 원인 추적
여기서 시야를 넓혀서, MongoDB 클러스터 전체의 쿼리 latency 분포를 다시 봤습니다.
(참고: count의 값은 비율만 맞춰 가짜 값을 넣었습니다)
| 시간 | p95 | max | count |
|---|---|---|---|
| 12:00~12:38 | 2~5 ms | 10~30 ms | 60~170/min |
| 12:39 | 5.97 s | 9.97 s | 149 |
| 12:40 | 7.44 s | 22.49 s | 227 |
| 12:41 | 5.9 ms | 218 ms | 73 |
| 12:42+ | 2~4 ms | 10 ms | 정상 |
2분간 클러스터의 거의 모든 쿼리가 1,000~10,000배 느려졌습니다. createIndexes뿐 아니라 find, insert, aggregate까지 모두요. 확인해보니 특정 컬렉션이나 특정 명령이 아니라 클러스터 전체가 한 번에 막힌 패턴이었습니다.
그리고 Mongo Atlas의 Performance Advisor를 봤더니, 만성 슬로우 쿼리들이 평소부터 누적되고 있던 게 보였습니다. 내원객 컬렉션에서 이름·전화번호로 검색하는 쿼리들이 인덱스를 안타고 20+만 건 컬렉션을 풀스캔하면서 평균 4.5초가 걸리고 있었고, 시간당 수백 회씩 돌고 있었어요. 더 심한 케이스는 평균 15초, 다른 테넌트의 비슷한 쿼리는 56초까지 측정됐고요.
평소엔 별다른 알람이 안 울렸기 때문에 이 만성 부하의 존재 자체를 인지하지 못하고 있었습니다.
만성 부하 + spark = cascade
여기서 의미 있는 가설이 나옵니다. 평소에는 이 풀스캔들이 클러스터의 여유분으로 흡수되어 "느린데 안 죽는" 상태였던 거예요. p95는 2~5ms로 깨끗해 보이지만, p99/max로 봐야 비로소 4.5초가 보이는 식이었거든요.
풀스캔(COLLSCAN)은 인덱스가 아닌 데이터 페이지 전체를 메모리(WiredTiger 캐시)로 끌어옵니다. WiredTiger 캐시는 MongoDB의 RAM 캐시 레이어로, 자주 쓰는 데이터/인덱스 페이지를 들고 있어서 쿼리 응답을 빠르게 해주는데요. 풀스캔이 잦으면 hot working set 페이지가 캐시에서 evict(밀려나옴)되면서 캐시 효율이 떨어집니다.
이게 만성적으로 누적되다가 어떤 임계점을 넘었을 때, 캐시 eviction이 폭주합니다. evict된 페이지가 다시 필요할 때마다 디스크에서 읽어야 하니까 디스크 IO가 폭증하고요.
실제로 Atlas Metrics를 보니, 같은 시점의 Disk IOPS가 평소 처리량 대비 burst 시점 약 66배 로 튀어 있었습니다. AWS EBS의 IOPS 한도에 닿으면 IO 큐에 적체되기 시작하고, 디스크 read latency가 평소 1ms에서 100ms 이상으로 폭증합니다. 그러면 모든 쿼리가 도매금으로 느려져요. 캐시 hit를 가정하고 짜인 인덱스 쿼리조차 cache miss로 떨어지면서 IO 큐에 끼는 거죠.
IOPS(Input/Output Operations Per Second)는 디스크가 1초에 처리할 수 있는 read/write 작업 수입니다. AWS EBS gp3 기준 인스턴스 사이즈마다 provisioned IOPS가 정해져 있고, 한도를 초과하면 큐잉됩니다. Disk Queue Depth가 0에서 두 자리수로 튀면 IO bound 상태가 됐다는 신호예요.
인과 체인 정리
지금까지의 데이터로 재구성하면 이렇습니다.
[만성 부하] 내원객 컬렉션 풀스캔이 시간당 수백 번 돌면서 WiredTiger 캐시 압박
↓
[임계점] 오후 12:39 시점, eviction이 빠르게 일어나기 시작
↓
[증폭] hot working set이 캐시에서 밀려나면서 평소 인덱스 쿼리들도 cache miss
↓
[폭발] Disk IOPS 66배 튐, AWS EBS IO 큐 적체
↓
[도매금 슬로우] 모든 쿼리가 1~10초로 느려짐
↓
[BFF 502] 5초 timeout에 걸려 BFF가 502 Bad Gateway 응답
createIndexes burst는 spark가 아니라 같은 시점의 다른 피해자였을 가능성이 높았어요. 무엇이 정확히 임계점을 넘게 했는지는 추가 단서가 필요하긴 하지만(트래픽 spike, 백그라운드 잡, 신규 테넌트 첫 풀스캔 등), 만성 fuel이 풀스캔이라는 건 확실했습니다.
선택과 이유
그래서 해결 방향은 두 갈래였습니다.
A. 풀스캔 제거 (인덱스 추가) — Performance Advisor가 짚어준 인덱스를 추가해서 4.5초/15초/56초 쿼리들을 ms 단위로 떨어뜨림. 만성 부하의 fuel 자체를 없애는 접근.
B. createIndexes hot path 호출 패턴 제거 — 인덱스를 매 요청마다 보장하던 코드를 테넌트당 1회만 호출하도록 변경. burst 시점의 동시 락 경쟁 가능성을 없애는 접근.
둘 다 필요한데, 우선순위는 A를 먼저입니다. createIndexes 호출 캐싱(B)만 적용하면 다음 cache eviction 임계점이 또 올 거예요. 풀스캔 자체를 막아야 캐시 압박이 사라집니다.
실제로 한 것
1. 권고 인덱스를 코드와 매핑
Performance Advisor가 권고한 인덱스를 그대로 받지 않고, 코드를 직접 보면서 어떤 메서드의 어떤 쿼리에 매핑되는지 확인했어요. Atlas가 권고하는 인덱스는 통계상 효과 있을 거라고 추정한 것이지, 실제 코드의 쿼리 형태와 정확히 맞는지는 별개거든요.
내원객 서비스의 논리를 확인 해 보니, 이름, 별칭, 전화번호 등 검색하는 메서드들이 공통적으로 조회 패턴을 만들고 있었습니다. Performance Advisor가 짚은 쿼리들과 정확히 같은 모양이었어요.
기존에 이 컬렉션엔 인덱스가 17개나 있었지만, prefix가 비슷한 것들이 있어도 특정 속성의 prefix가 없거나 정렬 키가 빠져 있어서 옵티마이저가 이 쿼리에는 못 쓰고 있었습니다. 그래서 4개를 새로 추가했어요. (정확한 조회 조건 순서로 묶은 복합 인덱스들을 생성함)
인덱스 필드 순서에는 ESR rule이라는 게 있는데요. Equality(등치 비교), Sort(정렬), Range(범위 비교) 순서로 배치하면 MongoDB 옵티마이저가 한 인덱스로 필터링과 정렬을 모두 처리할 수 있어요. (순서를 바꾸면 옵티마이저가 in-memory sort로 떨어집니다)
2. 진짜 정기 트래픽인지 검증
권고 인덱스가 일회성 콘솔 쿼리 때문에 잡힌 게 아닌지 의심해볼 필요가 있었어요. Atlas Performance Advisor는 윈도우 평균이라, 한 시간에만 폭발했어도 시간당 평균으로 환산되거든요.
Datadog의 mongo 스팬을 24시간 윈도우로 분포를 봤더니, 클라이언트 측 영업시간(KST 09:0021:00) 기준 활발한 메트릭을 확인했고, 새벽 02:0007:00에는 한 자리수로 떨어졌고요. 만약 사람이 콘솔(eg. datagrip, compass) 에서 친 쿼리라면 이런 곡선이 안 나온다고 생각했습니다.
호출 주체 또한 group by로 확인했는데요. 내원객 서비스의 HTTP 엔드포인트(검색, 중복 확인, 페이지네이션 조회 등)로 들어오는 트래픽이 전부였어요. 외부 도구의 직접 접속이 아니라 Gateway/클라이언트가 호출하는 정상 API 호출이었습니다.
결과
데이터 모델 인덱스 튜닝 작업
Rolling Index Build로 프로덕션 서비스 적용
이제 남은 과제는 두 가지입니다.
첫째, 무엇이 그 시점에 임계점을 넘게 했는지는 아직 명확하지 않습니다. 풀스캔이 만성 fuel이라는 건 확인했지만, "왜 하필 12:39였나"는 트래픽 spike, 새 테넌트의 첫 풀스캔, 백그라운드 잡 중 하나일 텐데 그건 추가 데이터가 필요해요. 다만 fuel만 없애도 다음 임계점이 안 오니까 우선순위는 낮습니다.
둘째, 다른 메서드들도 인덱스 적합도가 의심되긴 합니다. Performance Advisor가 지금은 짚지 않았지만, 트래픽 패턴이 바뀌면 새 슬로우 쿼리가 잡힐 수 있어요. 정기적으로 Performance Advisor를 보는 운영 루틴이 필요할 것 같습니다. (데이터독 모니터로 Lag과 스캐닝 문서 개수 조건을 통한 알람을 추가했어요)
정리하며
이번 디버깅에서 가장 크게 배운 건 표면 trigger와 만성 부하를 분리해서 봐야 한다는 점이었어요. burst 시점에 가장 눈에 띄는 건 createIndexes였지만, 그건 결과였지 원인이 아니었습니다.
진짜 원인은 평소에 멀쩡해 보이던 풀스캔이 만성적으로 데이터베이스의 캐싱 압박을 누적시키고 있었던 거고, 어떤 임계점에서 그 압박이 cascade로 번진 거였죠.
p95/p99만 보면 "느려도 안 죽는" 상태가 깨끗하게 보입니다. 그런데 그 안에 만성 fuel이 쌓이고 있을 수 있어요. Performance Advisor 같은 도구가효과 있을 인덱스를 미리 알려주는 건 이런 만성 부하를 가시화해주는 셈인데, 평소에 무시하고 지내다가 burst 한 번에 비싼 대가를 치르게 되는 거죠.
그리고 가설은 검증되기 전까지는 가설일 뿐이라는 것도요. createIndexes가 X 락을 잡아서 cascade를 만든다는 가설은 첫 번째로 그럴듯해 보였지만, Hybrid Index Build 동작을 정확히 알고 나니 흔들렸습니다. 만약 이미 만들어진 인덱스도 X lock을 잡나? 란 되짚음이 없었다면 잘못된 가설 위에서 잘못된 해결을 했을 수도 있었어요.
분산 시스템 디버깅에서 trace는 시작점이지 끝이 아니더라고요. 트레이스가 "여기가 느려요"라고 가리키는 지점은, 진짜 원인의 피해자일 수도 있다는 걸 잊지 말아야겠습니다.
