DB가 죽었다는 알림이 왔다. DB는 죽은 적이 없었다

아침에 슬랙을 열었더니 CRITICAL 알림이 네 개 쌓여 있었다.

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

마지막 줄이 제일 무섭다. DB가 죽었다는 뜻이니까. 넷을 한 화면에서 보면 이야기가 하나 그려진다. DB가 힘들어했고, 그래서 쿼리가 밀렸고, 그래서 요청이 타임아웃 났고, 결국 헬스체크까지 실패했다. 그럴듯한 이야기다.

그래서 나는 DB 지표부터 열었다. 그 이야기는 첫 화면에서 무너졌다.

DB는 21시간 내내 한가했다

장애 시각을 포함한 21시간 구간의 RDS 지표를 5분 단위로 뽑았다. 252개 데이터포인트.

지표	최소	최대
CPU	4.6%	19.7%
커넥션	53	73
CPU 크레딧 잔고	576	576
읽기 지연	0s	0.01s
쓰기 지연	0.01s	0.08s

CPU는 20%를 넘긴 적이 없고, 크레딧 잔고는 최소값과 최대값이 같다. 하나도 안 썼다는 뜻이다. 쓰기 지연은 최대 80밀리초. RDS Proxy도 확인했다. 커넥션 대여 지연 최대 26밀리초, 백엔드 커넥션 최대 36개. 어디에도 8초, 10초짜리 쿼리를 설명해줄 숫자가 없다.

DB는 죽지 않았다. 심지어 바쁘지도 않았다.

요청 하나가 대서양을 스물다섯 번 건넌다

그럼 8초짜리 쿼리는 어디서 나왔나. 구조를 보면 답이 나온다.

우리 서비스는 두 리전에서 돈다. us-east와 eu-west. primary DB는 us-east에 하나뿐이고, eu-west 앱의 읽기는 로컬 레플리카가 받지만 쓰기는 전부 대서양을 건너, RDS Proxy를 경유해 us-east primary로 간다.

쓰기 횟수가 문제였다. 연습 기록 저장 요청(POST /customer/practice/attempts) 하나를 코드로 따라가며 세어봤다. 자산 upsert 1회, 사전 집계 읽기 3회, 학습 시도 트랜잭션 4회, 러너의 재조회 1회, 진도 갱신 23회, 스트릭 트랜잭션 약 6회, 통계 트랜잭션 2회, 복습 상태 갱신 23회. 독립된 인터랙티브 트랜잭션 세 덩어리에 걸쳐 대략 스물다섯 번.

로그에 그 숫자가 그대로 찍혀 있었다.

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

쿼리 25개, 11.7초. 이 요청은 실패하지도 않았다. 11.7초를 버틴 끝에 201로 성공했다.

여기서 하나 정직하게 밝혀둘 게 있다. 나는 이 왕복 하나에 몇 밀리초가 드는지 재지 않았다. 코드 주석 하나는 리전 간 RTT를 220밀리초라고 적어뒀고, 다른 주석은 문장당 80~100밀리초라고 적어뒀다. 둘 중 뭐가 맞는지 확인하지 않은 채로 나는 "25 x 220ms = 5.5초"라는 계산을 이슈 본문에 적었다. 지금 다시 보면 그건 측정이 아니라 인용이다. 정확한 진술은 이렇다. 왕복 횟수는 셌고(25), 왕복당 비용은 재지 않았다. 그래도 결론은 흔들리지 않는다. 대서양을 스물다섯 번 왕복하면 비용은 초 단위로 쌓인다.

EU 아침 피크(06:00~06:10 UTC)에 3초를 넘긴 primary 쓰기가 57건 몰렸다. LearningAttempt.create 8,989ms, UserActiveDate.upsert 9,070ms, LearningAttempt.findUnique 10,561ms. 요청이 서로 밀리면서 왕복 지연이 쌓였다.

알림 두 개는 그 틈에서 나왔다.

알림 1과 2: 5초짜리 트랜잭션이 9.3초를 견디지 못했다

스트릭 갱신 코드는 이렇게 생겼다.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... 리전을 건너가는 쿼리 여섯 개 ...
});

옵션 객체가 없다. 그래서 Prisma의 기본 인터랙티브 트랜잭션 타임아웃인 5,000밀리초가 적용된다. 평소엔 문제가 없다. 리전을 건너지 않는다면.

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9,326밀리초. 그리고 이게 P2028이 되고, 요청은 게이트웨이에서 504가 된다.

이 코드는 우리 코드베이스에서 혼자만 무방비였다. 다른 트랜잭션 경로들은 withTxRetry 유틸을 통과하는데, 그 유틸은 타임아웃을 8초로 올리고 P2028을 재시도 대상으로 잡는다. 스트릭 갱신만 그 우산 밖에 남아 기본값 5초를 쓰고 있었다.

알림 4: 헬스체크가 자기가 감시하던 병목을 통과했다

가장 무서웠던 "DATABASE 서비스 다운"이 실은 가장 어이없었다.

헬스체크 코드는 잘 짜여 있었다. SELECT 1을 2초 타임아웃으로 던지고, 실패하면 500밀리초 쉬었다가 한 번 더 시도하고, 그것도 실패하면 CRITICAL 알림을 쏜다. 앱의 Prisma 풀과 섞이지 않도록 전용 커넥션 풀(최대 2개)까지 따로 뒀다. 앱 풀이 고갈돼도 헬스체크는 살아 있게 하려는 설계다.

그런데 이 프로브가 DB에 닿는 경로는 격리되지 않았다.

// health.service.ts:139
// DIRECT_DATABASE_URL 이 있으면 그걸 쓰고, 없으면 DATABASE_URL 로 폴백한다

DIRECT_DATABASE_URL이 설정돼 있지 않았다. 폴백이 걸렸고, DATABASE_URL은 앱의 쓰기가 몰려 있는 바로 그 RDS Proxy를 가리킨다. 즉 eu-west의 헬스 프로브가 던진 SELECT 1은 대서양을 건너, 지금 막히고 있는 그 프록시를 통과해서, us-east primary까지 갔다 와야 했다. 2초 안에.

코드는 이 사실을 알고 있었다. 폴백이 걸릴 때 이런 경고를 남기게 돼 있다.

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

로그에 이 줄이 그대로 찍혀 있었다. 누구도 읽지 않았을 뿐이다.

결정적인 증거는 두 리전이 같은 시각에 함께 실패했다는 것이다. 12:02:17, us-east 태스크의 헬스체크가 타임아웃. 12:02:18, eu-west 태스크도 타임아웃. 지역 문제였다면 한쪽만 죽었어야 한다. 둘이 함께 죽었다는 건 둘이 공유하는 것, 즉 프록시 경로가 원인이라는 뜻이다.

그다음은 예정된 수순이다. 헬스체크가 두 번 다 실패했으니 /public/health가 503을 뱉고, 오케스트레이터가 이 태스크를 문제 있는 것으로 보고 교체한다. 4분 뒤 새 태스크가 떴다. 새 태스크는 부팅하자마자 똑같은 헬스체크 타임아웃을 다시 맞았다. 태스크를 바꾼다고 대서양이 좁아지지는 않으니까.

"DATABASE 서비스 다운"은 장애의 증상이 아니었다. 감시 장치가 감시 대상의 혼잡한 길을 걸어보고 나서, 자기가 힘들다고 보고한 것이었다.

어드민 500은 별건이었다

여기서 네 알림을 하나로 묶고 싶은 유혹이 온다. 나도 처음엔 그렇게 정리하려 했다. 하지만 어드민 500은 뿌리가 달랐다.

GET /admin/dashboard/stats가 인기 단어를 뽑을 때 최근 7일로 필터를 건다. 그런데 그 필터가 걸리는 테이블(category_attempt)에는 자기 날짜 컬럼이 없다. 날짜는 조인되는 learning_attempt 쪽에만 있다. 그래서 Postgres는 category_attempt를 날짜로 미리 잘라낼 방법이 없고, 전체 이력을 다 훑어야 한다. 인덱스를 아무리 잘 깔아도 이 필터를 선택적으로 만들 수 없다.

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

statement_timeout이 8,000밀리초다. 8,009밀리초. 9밀리초 차이로 죽었다. 리전과는 상관없는, 테이블이 커지면 언젠가 반드시 터질 풀스캔이었다.

알림 네 개 중 셋이 한 뿌리였고, 하나는 아니었다. 네 개가 한 화면에 떴다고 원인이 하나인 건 아니다.

기각한 가설 하나

한 가지 그럴듯한 용의자가 있었다. 06:00 버스트 직전에 도는 device-cleanup 크론이 락 경합을 일으켰다는 가설. 시간대가 맞아떨어져서 꽤 설득력 있었다.

두 리전의 로그를 05:30~06:15 구간으로 훑었다. 크론 관련 로그가 한 건도 없었다. 느렸던 Device.updateMany의 경로를 확인하니 크론의 벌크 업데이트가 아니라 /v2/public/auth/refresh, 즉 평범한 유저의 토큰 갱신 요청이었다. 가설은 실측으로 기각됐다. 시간대가 겹친다는 건 상관관계고, 로그에 없다는 건 사실이다.

왕복을 접었다

처방은 두 갈래다. 증상을 견디는 길이 있다. 타임아웃을 8초로 늘리고, 풀을 키우고, 재시도를 붙인다. 비용 자체를 없애는 길도 있다. 왕복 수를 줄인다.

우리는 둘 다 했다. 스트릭 트랜잭션에 withTxRetry를 씌우는 건 반창고지만 필요한 반창고였다. 하지만 진짜 처방은 왕복을 접는 것이었다.

그 도구는 이미 만들어져 있었다. 6월 27일자 마이그레이션에 create_practice_attempt_v1이라는 서버사이드 함수가 있었다. 세션 잠금, 조회, 삽입, 세션 메타 갱신, 사전 집계 읽기를 SQL 함수 하나로 접어 왕복 한 번에 끝내는 함수다. 멱등성까지 갖춰져 있다(같은 client attempt id로 두 번 부르면 두 번째는 기존 행을 돌려주고 inserted=false를 반환한다).

그런데 이 함수를 켜는 기능 플래그 PRACTICE_ATTEMPT_SINGLE_RT_ENABLED가 기본값 false로, 프로덕션에서 꺼져 있었다.

리전을 없애거나 active-active로 가는 대신, 우리가 한 일은 이미 만들어 둔 스위치를 켜는 것이었다.

카나리: 무엇을 보고 판정할 것인가

플래그를 eu-west에만 켰다. us-east는 대조군으로 껐다. task definition 786에서 787로 올리고 롤링 배포.

여기서 판정 지표를 뭘로 삼을지가 이 이야기의 핵심이다. 지연시간은 함정이다. 트래픽이 한가한 시간에 배포하면 아무것도 안 고쳐도 p95가 좋아진다. 실제로 지연시간은 좋아졌다. p50이 2,784ms에서 2천ms 아래로 내려갔다. 하지만 그건 증거가 약하다.

대신 나는 요청당 쿼리 수를 봤다.

배포 전  n=85   avg query_count = 22.0
배포 후  n=49   avg query_count = 15.3

쿼리 수는 부하와 무관한 per-request 지표다. 트래픽이 많든 적든, 요청 하나가 쿼리를 몇 개 던지는지는 코드 경로가 결정한다. 22에서 15.3으로, 약 7개가 줄었다. 그리고 그 7개는 우리가 함수 하나로 접은 쿼리 목록(세션 잠금 + 조회 + 삽입 + 세션 메타 + 사전 집계 읽기)의 개수와 정확히 일치한다. 코드 경로가 실제로 바뀌었다는 증거는 이 숫자다. 지연시간이 아니라.

배포 후 표본은 15분간 49건이다. 그 창에서 5xx도 P2028도 0건이었지만, 같은 날 같은 길이의 "배포 전" 에러 수를 나란히 재두지는 않았다. 이 플래그는 attempt 저장만 접는다. 스트릭 트랜잭션은 여전히 리전을 건너간다. 그날 창에서 P2028이 0건이었던 건 운이 좋았다는 뜻이지 증명은 아니다.

배포는 성공했는데 플래그는 사라질 뻔했다

카나리를 켠 방식에는 대가가 있었다. 787은 콘솔에서 직접 등록한 task definition이다. 다음 정식 배포가 돌면 CD 파이프라인이 플래그 없는 task definition으로 덮어쓴다. 치명적이진 않다(덮어쓰면 안전한 OFF로 돌아간다). 다만 개선이 조용히 사라진다.

그래서 terraform으로 승격시켜야 했는데, 여기서 두 번째 함정이 나왔다. terraform 워크플로는 develop push에서 staging만 apply하고, production은 main push에서만 apply한다. 그런데 staging에는 애초에 eu-west 리전이 없다. 즉 프로덕션 eu-west 변경을 담은 PR을 develop에 머지하면 아무 일도 일어나지 않는다. base를 main으로 바꿔야 했다.

세 번째 함정이 있었다. main에 직접 머지하면 develop이 뒤처지고, 되돌려 병합하지 않으면 다음 릴리스가 이 변경을 revert해버린다. back-merge PR을 따로 만들어야 했다.

"terraform apply가 성공했다"와 "프로덕션에 반영됐다"는 다른 문장이다.

남은 것

"DB 다운" 알림이 오면 DB 지표부터 열어야 한다. 알림의 이름은 알림을 쏜 코드가 붙인 것이지 원인이 붙인 게 아니다. 우리 헬스체크는 앱 풀과 격리된 전용 풀까지 만들어 뒀는데도, 정작 DB로 가는 길이 같아서 앱과 함께 막혔다. 격리는 자원만 나눠서는 안 되고 경로도 나눠야 한다.

타임아웃을 5초에서 8초로 늘리면 그날의 알림은 멈춘다. 하지만 요청은 여전히 대서양을 스물다섯 번 건넌다. 트래픽이 조금만 더 늘면 8초도 부족해진다. 증상을 견딜지 비용을 없앨지는 미리 정해두는 편이 낫다. 비용의 정체가 "횟수 x 거리"라면 줄여야 할 건 횟수다.

지연시간은 부하에 흔들리고, per-request 지표는 안 흔들린다. 성능 수정을 배포하고 p95가 좋아졌다고 안심하기 전에, 요청 하나가 하는 일의 개수가 실제로 줄었는지를 봐야 한다. 그 숫자는 새벽에 배포하든 점심에 배포하든 같다.

나는 왕복 횟수를 세었고, 왕복당 지연은 코드 주석에서 가져다 썼다. 그 주석 두 개는 서로 다른 값을 말하고 있었다. 결론이 바뀌지 않았으니 다행이지만, 다음번엔 결론이 바뀔 수도 있다. 재지 않은 숫자는 재지 않았다고 쓰자.