갑자기 모든 BFF 서비스에서 500이 발생했던 이유
배경
점심시간이 얼마 안 남은 오후 12:40 분 경, 운영 환경의 BFF(Backend For Frontend) 세 개가 동시에 에러를 토하기 시작했습니다. 인터널 BFF, 유저향 BFF, 외부 파트너(Open) BFF까지 세 서비스 모두 500과 502가 같이 폭증했어요.
BFF는 클라이언트(웹/앱)와 백엔드 마이크로서비스 사이에 두는 얇은 게이트웨이입니다. 클라이언트는 BFF 하나만 호출하고, BFF가 내부의 여러 백엔드 API를 조립해서 응답을 만들어 돌려주는 구조죠. 이 글에 나오는 세 BFF도 각각 다른 클라이언트(인터널 앱, 유저 앱, 외부 파트너 API)에 응답을 주는 동일한 패턴입니다.
세 서비스가 같은 시점에 같이 죽었다는 건 보통 두 가지 중 하나거든요. 첫째는 공통 의존성이 무너졌을 때, 둘째는 트래픽 자체가 spike 쳤을 때. 이 글은 그 진짜 원인을 찾아 들어가는 과정과, 표면 증상 뒤에 어떤 메커니즘이 숨어 있었는지에 대한 기록입니다.
문제
먼저 1시간치 에러 스팬 수를 BFF별로 잡았는데요. 한쪽 BFF가 14,844건으로 전체의 94%를 차지했고, 나머지 둘도 평소 대비 비정상적으로 많았습니다.
분 단위로 시간 분포를 보면 03:3903:40 UTC(12:3912:40 KST) 2분간 폭증한 게 명확하게 보였어요. 평소 분당 150~280건이던 게 1,299 → 1,761로 한 번 튀고 다시 200대로 돌아왔거든요. 즉 burst 자체는 짧았지만, 그 시점에 뭔가 클러스터 전반을 흔든 게 있었던 거죠.
에러 메시지 패턴은 두 종류로 나뉘었습니다. 유저 앱 쪽에서는 다운스트림 내원객 서비스가 400 BAD_REQUEST를 반환했고, 외부 파트너 BFF 쪽에서는 시술 상품 서비스에 대한 ReadTimeoutException이 찍혔습니다. 흥미로운 건 timeout이 정확히 5초였다는 점이고, BFF가 외부로는 502 Bad Gateway를 던지고 있었어요.
1차 가설: 다운스트림이 죽었나?
자연스러운 첫 가설은 "다운스트림 API가 죽어서 BFF가 5초 timeout 뜨고 502 던지는 것"이었습니다. 하지만 트레이스를 까보니 그게 아니었어요.
외부 파트너 BFF의 502 응답 한 건을 골라서 데이터독의 트레이스 콜체인을 따라가봤더니, 외부 파트너 BFF는 5,005ms에 502를 응답했지만 다운스트림 상품 서비스 자체는 status:ok로 5,002ms에 200을 응답하고 있었어요. 즉 백엔드는 살아있는데 응답이 그냥 늦었던 거고, BFF의 read timeout 5초를 넘긴 거였죠.
5초의 대부분은 시술 상품 서비스 안의 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 분포를 다시 봤습니다.
| 시간 | 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를 봤더니, 만성 슬로우 쿼리들이 평소부터 누적되고 있던 게 보였습니다. 내원객 컬렉션에서 이름·전화번호로 검색하는 쿼리들이 인덱스 없이 21만 건 컬렉션을 풀스캔하면서 평균 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가 평소 22.7/s → burst 시점 1,500/s (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 22.7 → 1,500 (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 임계점이 또 올 거예요. 풀스캔 자체를 막아야 캐시 압박이 사라집니다.
마침 B는 동료가 이미 작업해서 main에 머지된 상태였고, 저는 A에 집중하기로 했습니다.
실제로 한 것
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)에 시간당 35242건이 도는 명확한 영업시간 곡선이 나왔습니다. 새벽 02:00~07:00에는 한 자리수로 떨어졌고요. 사람이 콘솔에서 친 쿼리라면 이런 곡선이 안 나온다고 생각했습니다.
호출 주체 또한 group by로 확인했는데요. 내원객 서비스의 HTTP 엔드포인트(검색, 중복 확인, 페이지네이션 조회 등)로 들어오는 트래픽이 전부였어요. 외부 도구의 직접 접속이 아니라 BFF/클라이언트가 호출하는 정상 API 호출이었습니다.
3. 알림 서비스에서 두 번째 사례 발견
같은 burst 시간대에 알림 로그 컬렉션의 슬로우 쿼리도 Performance Advisor에 잡혀 있었습니다. 발송 상태 + 요청 시각 조합 인덱스가 권고됐고, 평균 968ms에 36만 건 풀스캔이었어요.
코드를 찾아보니 알림 서비스에 "미확정 메시지를 회수하는 백그라운드 폴러"가 있었는데, 그게 정확히 그 쿼리 패턴이었습니다. N분 이상 REQUESTED 상태로 묶여있는 메시지를 다시 확인하는 로직이었고, 배치 잡으로 정기적으로 도는 게 확실했어요. 마찬가지로 ESR rule에 맞는 복합 인덱스 하나만 추가했습니다.
4. 운영 적용 순서 명시
PR에 인덱스 추가 코드만 머지하면 위험합니다. 새 인덱스 4개를 21만 건짜리 컬렉션에 동시 빌드하면, 그게 또 다른 cache eviction burst를 일으킬 수 있거든요. 이번 장애의 만성 fuel을 없애려다가 새로운 burst를 만드는 격이죠.
Atlas UI의 Performance Advisor에서 "Create Index" 버튼을 직접 클릭. Atlas가 자동으로 Rolling Index Build로 만들어줍니다(secondary부터 순차적으로 빌드한 다음 primary는 step-down 후 빌드해서 운영 트래픽에 영향이 거의 없는 방식).
그 후 수정 PR을 머지함.
createIndexes호출이 와도 MongoDB가 "이미 있음" 응답을 즉시 줘서 부하 없음.인덱스 생성 호출에 대한 캐싱 작업은 이미 main에 있어서, 향후 인덱스 보장 호출 빈도도 테넌트당 1회로 제한됨.
결과
내원객 서비스와 알림 서비스에 인덱스 튜닝 작업
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는 시작점이지 끝이 아니더라고요. 트레이스가 "여기가 느려요"라고 가리키는 지점은, 진짜 원인의 피해자일 수도 있다는 걸 잊지 말아야겠습니다.
