[봄봄] 서비스 장애

 

 

배경

 

아침 일찍 뉴스레터 챌린지를 하던 중 

갑자기 서비스가 멈췄습니다.

 

자세히 말하면 모든 API가 먹통이 되었습니다.

측정 단위가 5분이라 19.1%로 보이는데 그때 당시 피크가 30%를 넘었습니다.

수익화가 안되기 때문에 제일싼 t4g.micro를 쓰기에 CPU 사용률 10%를 넘기는 순간 크레딧이 소모됩니다.

이날 처음으로 1년만에 크레딧이 전체 소진됐습니다.

 

다행히? 서버는 터졌다는 알림이 없었기에 애플리케이션이나 DB쪽 문제일 것 같았습니다.

바로 다음에 로그를 봤습니다.

 

그 당시 에러입니다.

 

"Connection is not available" 

 

이미 커넥션이 11개를 사용 중인데 21개가 대기 중 이었습니다.

 

뭐가 문제였을까?? 

 

문제 찾기

DB쪽이 문제인 것 같다는 생각이 들어 traces를 봤는데 확실히 DB쪽 문제였습니다.

 

바로 DB 모니터링을 확인해보았습니다.

먼저 에러로그를 살펴보았습니다.

이유는 설명되어있지 않고 Received SHUTDOWN으로만 되어있었습니다.

 

지금 5분단위라서 그러는데 당시 1분단위로 보았을 때 순간 피크가 30%가 넘어갔습니다.

다만 그 이상으로는 올라가지 않았다 즉 80%, 90%, 100%는 커녕 30%잠깐 찍고왔을 뿐이었습니다.

 

운영한지 1년동안 크레딧이 거의 소모되지 않았았다가 딱 이날 7월 24일에 한 번에 전부 소진됐습니다.

우리 DB는 t4g.micro다  micro는 CPU 사용률 10%부터 크레딧을 소모합니다.

(small은 20%, medium은 30%, large는 40%)

 

어차피 RDS는 CPUSurplusCreditBalance을 무제한을 사용할 수 있어서 비용은 발생하지만 CPU가 순간적으로 높아져도 정상적으로 동작합니다.

 

그렇다면 메모리쪽은 어떨까?

 

여유 메모리가 얼마 남지 않았고 스왑도 높긴했지만 OOM은 나지 않았습니다.

아래처럼 근 3개월을 봐도 비슷한 수치였습니다.

 

 

그렇다면 저장소는 어땠을까? 

우리 RDS의 저장소에서 사용하는 EBS는  gp3입니다.

 

gp3 기본 한도는 용량에 상관없이 3,000 IOPS다 그것의 메트릭을 보면 반절 정도만 사용됐으니 IOPS부족으로 인한 디스크 스로틀링이나 병목은 아니라는 뜻입니다.

디스크 큐 길이도 7월 24일 당시에 1미만이었다.  일상적으로 5 미만이면 안정권입니다.

레이턴시도 평소와 큰 차이가 없습니다.

througghput 역시 평소와 비슷한 수치였습니다.

t시리즈 small 이하는 Enable Performance Insights를 사용할 수 없기 때문에 에러찾기가 어려웠습니다.

 

그래서 일단은 다음으로 슬로우 쿼리를 확인했습니다.

그날의 슬로우 쿼리를 보는데 평소에는 거의 없는 해당 시간대에 집중적으로 1,653개의 슬로우 쿼리가 존재했습니다.

 

분석해보니 아래와 같았습니다.

• 집중 발생: 09:15~09:44 KST
• 슬로우 쿼리: 1,653건
• 누적 실행 시간: 15,232초
• 누적 Lock time: 8,455초
• 최다 발생: 09:23 176건
• SPRING_SESSION 갱신: 594건, Lock time 약 6,796초
• article_read_history 쓰기: 59건, Lock time 약 1,448초

우리 서비스는 세션 로그인을 사용면서 분산서버이기 대문에 세션 데이터를 공통으로 저장하기 위해 세션 DB를 사용하고 있습니다. 왜냐하면 오직 세션 데이터만을 위해 캐시층을 도입하는게 오버엔지니어링이라 생각해서 하지 않았습니다.

 

DB에 한계가 오니 정말 필요한 이유가 타당할 때 도입하려고 했는데 처음에는 지금인가? 싶었습니다.

하지만 뭔가 근본적인 원인은 아닌 것 같았습니다.

 

그래서 croudfront에서 근 2주 트래픽을 살펴보았습니다.

 

평소보다 트래픽이 높았던 것도 아니었는데 딱 그날만 DB 포화로 인해 에러가 발생률이 엄청높았습니다.

그렇담 세션DB가 근본적 원인이라기보다는 이미 불난집에 부채질하는 모습일 것 같았습니다.

그래서 근본적으로 불난 곳을 찾으려고 이곳 저곳을 뒤졌습니다.

RDS 에러 로그를 봐도 정확한 원인을 말해주지 않고 Received SHUTDOWN이라고만 떠서 조금 더 지켜보기로 했습니다.

 

그리고 에러는 25일, 26일, 27일, 28일 잠잠했다가 7월 29일, 31일 연달아 터졌습니다.

29일은 셧다운은 안 됐는데 31일은 셧다운이 됐습니다.

슬로우 쿼리를 분석해보면

7월 29일

09:30~09:44에 하루 슬로우 쿼리의 89.7%, 실행 시간의 94.6%, Lock time의 99.6%가 집중됐습니다.

• SPRING_SESSION: 306건
  • 실행 시간 2,013.6초
  • Lock time 1,049.4초
  • 동일한 PRIMARY_ID를 갱신하는 쿼리가 약 50초씩 대기
• 월간 랭킹: 101건
  • 평균 실행 시간 3.99초
  • 호출당 평균 378,779행 검사
  • 전체 검사 행의 98.0%
  • Lock time은 0.69초로 잠금 문제는 아님
• 별도로 알림 조회 1건이 114.2초 걸렸지만 Lock time은 거의 0

랭킹 조회가 논리 읽기 비용을 크게 만들고 있던 상황에서 동일 세션 갱신이 겹치며 잠금 대기가 폭증한 패턴양상을 보이고 있습니다.

7월 31일

09:30~09:44에 하루 슬로우 쿼리의 91.4%, 실행 시간의 97.4%, Lock time의 99.7%가 집중됐습니다.

• SPRING_SESSION: 447건
  • 실행 시간 3,998.1초
  • Lock time 2,586.7초
• article_read_history: 35건
  • 실행 시간 847.3초
  • Lock time 426.6초
  • 동일 회원·Article 조합의 INSERT IGNORE가 최대 약 52초 잠금 대기
• 월간 랭킹: 130건
  • 평균 실행 시간 5.06초
  • 호출당 평균 425,484행 검사
  • 전체 검사 행의 98.5%
  • Lock time은 0.68초

특히 09:34와 09:41에 두 차례 파동이 있었고, SPRING_SESSION과 article_read_history의 Lock time이 전체 잠금 대기의 약 96%를 차지했습니다.

 

그런데 여기서 큰 문제하나를 발견하게됐습니다.

 

상위 20명 조회가 만든 1억 7천만 번의 행 검사

장애가 집중된 네 날짜의 Slow Query 로그를 분석하자, 예상보다 훨씬 뚜렷한 공통점이 발견됐습니다.

날짜	요일	전체 Slow Query	누적 실행 시간	누적 Lock time	누적 검사 행	주요 집중 시간
7월 24일	금요일	1,739건	16,520.5초	8,461.2초	14,896,810행	09:15~09:44
7월 29일	수요일	985건	4,947.6초	1,084.1초	39,051,523행	09:30~09:44
7월 31일	금요일	1,654건	10,487.0초	3,137.4초	56,162,588행	09:30~09:44
8월 3일	월요일	1,438건	13,182.6초	4,369.6초	67,600,413행	07:41~07:44, 09:00~09:29

 

첫 번째 표의 실행 시간과 잠금 시간은 해당 날짜에 발생한 모든 Slow Query를 합산한 결과입니다. 이 가운데 어떤 쿼리가 가장 많은 데이터를 반복해서 확인했는지 알아보기 위해 Rows_examined를 쿼리별로 분류했습니다.

그 결과 월간 랭킹 조회가 전체 검사 행의 대부분을 차지하고 있었습니다.

날짜	전체 누적 검사 행	기존 랭킹 조회 검사 행	비중
7월 24일	14,896,810행	14,264,269행	95.8%
7월 29일	39,051,523행	38,241,527행	97.9%
7월 31일	56,162,588행	55,299,176행	98.5%
8월 3일	67,600,413행	66,590,917행	98.5%

 

네 날짜 동안 Slow Query가 검사한 행은 총 1억 7,871만 건이었습니다. 그중 월간 랭킹 조회가 검사한 행은 약 1억 7,439만 건으로, 전체의 97.6%를 차지했습니다.

 

여기서 Rows_examined는 테이블에 존재하는 고유한 행의 개수가 아닙니다. MySQL이 쿼리를 처리하면서 필터링과 조인을 위해 확인한 테이블 행과 인덱스 엔트리의 누적 횟수입니다. 같은 행을 여러 번 확인했다면 그 횟수만큼 중복으로 집계됩니다.

 

월간 랭킹 API가 반환하는 결과는 상위 20명뿐이었습니다. 하지만 기존 쿼리는 랭킹 대상 회원 약 1,680명을 먼저 조회한 뒤 모든 회원에 대해 RANKING, CHALLENGE, STREAK 배지를 조회하고 있었습니다. 이후 결과를 정렬하고 가장 마지막 단계에서 LIMIT 20을 적용했습니다.

 

사용자에게 보여줄 회원은 20명이었지만, 데이터베이스는 약 1,680명의 배지 정보를 모두 계산한 다음 나머지 1,660명의 결과를 버리고 있었던 것입니다.

 

원인을 더 정확하게 확인하기 위해 EXPLAIN ANALYZE로 기존 쿼리의 실행 계획을 분석했습니다. 단순히 쿼리가 느리다는 사실에 그치지 않고, 어느 단계에서 시간이 사용되고 같은 작업이 몇 번 반복되는지 확인했습니다.

 

개선 전 실행 계획. 약 1,680명의 회원마다 세 종류의 배지 조회를 반복한 뒤 마지막에 LIMIT 20이 적용되고 있습니다.

실행 계획에서 RANKING, CHALLENGE, STREAK 배지 조회의 loops는 모두 1,680으로 나타났습니다. 약 333행이 저장된 badge 테이블을 랭킹 대상 회원마다 세 차례 반복해서 확인한 것입니다.

실행 계획을 단순 계산하면 다음과 같습니다.

1,680명 × 배지 333행 × 배지 조회 3회
≈ 최대 1,678,320회의 행 방문

 

반면 최종 결과를 20명으로 제한하는 LIMIT 20은 모든 배지 조인과 정렬이 끝난 뒤에 적용되고 있었습니다.

 

실행 시간도 같은 사실을 보여줬습니다. monthly_reading_snapshot과 member를 조회하는 과정은 약 29ms에 끝났고, 최종 정렬 역시 약 9ms에 불과했습니다. 전체 실행 시간 1.28초 중 약 1.24초가 배지 조인에 사용됐습니다. 전체 실행 시간의 약 97%가 최종 결과에 포함되지 않을 회원의 배지를 반복해서 조회하는 과정에서 발생한 것입니다.

분석 대상이었던 월간 랭킹 Slow Query 389건은 호출당 평균 약 44만 행을 검사했습니다. 이 가운데 한 번의 호출에서 556,630행을 검사한 사례도 확인됐습니다.

 

다만 이 결과가 월간 랭킹 조회에서 전체 CPU의 97.6%를 사용했다는 의미는 아닙니다. Rows_examined는 SQL별 CPU 점유율이 아니라 MySQL이 수행한 논리적인 탐색량을 나타냅니다. Slow Query 로그만으로는 각 SQL이 실제로 사용한 CPU 비율을 직접 계산할 수 없습니다.

 

당시 긴 실행 시간과 잠금 대기에는 SPRING_SESSION, article_read_history 같은 다른 쿼리도 영향을 주고 있었습니다. 월간 랭킹 조회가 장애를 단독으로 발생시켰다고 볼 수는 없습니다.

 

그럼에도 월간 랭킹 조회는 호출될 때마다 수십만 행을 반복해서 확인하면서 데이터베이스의 논리 읽기와 CPU 기본 부하를 높이고 있었습니다. 평상시에는 이 비용을 감당할 수 있더라도 세션 잠금이나 검색 작업이 겹치면 각 쿼리의 처리 시간이 길어지고 커넥션 점유 시간도 함께 증가할 수 있습니다.

하나의 쿼리가 장애를 직접 발생시켰다기보다, 다른 병목이 발생했을 때 그 영향을 크게 증폭시키는 구조였던 것입니다.

 

필요한 데이터부터 줄이기

실행 계획을 분석한 결과, 문제는 LIMIT 20이 없어서가 아니라 너무 늦게 적용된다는 점에 있었습니다.

API 응답 형식과 정렬 기준은 그대로 유지하면서 쿼리의 실행 순서를 변경했습니다. 기존에는 약 1,680명의 배지를 모두 조회한 뒤 상위 20명을 선택했지만, 개선 후에는 월간 랭킹 상위 20명을 먼저 확정하고 선택된 회원에 대해서만 배지를 조회하도록 했습니다.

개선 전

전체 랭커 약 1,680명 조회
→ 1,680명의 배지 조회
→ 전체 결과 정렬
→ 상위 20명 반환

개선 후

전체 랭킹 스냅샷 조회 및 정렬
→ 상위 20명 선택
→ 20명의 배지 조회
→ 결과 반환

이 변경으로 배지를 조회하는 대상 회원은 약 1,680명에서 20명으로 줄었습니다. 반복 횟수만 비교해도 약 84배 감소한 셈입니다.

전체 회원 수가 2,000명에서 5,000명으로 늘어나더라도 배지 조회 대상은 여전히 상위 20명입니다. 회원 수 증가는 상위 회원을 정렬하고 선택하는 단계에는 영향을 줄 수 있지만, 회원별 배지 조회 횟수를 직접 증가시키지는 않습니다.

인덱스가 필요할까?

처음 쿼리를 개선할 때는 배지 조회의 반복적인 테이블 스캔을 제거하기 위해 세 개의 복합 인덱스도 함께 추가해야하나? 싶었습니다.

(member_id, badge_category, period_year, period_month)
(member_id, badge_category, created_at DESC)
(member_id, badge_category, streak_day_count DESC, created_at DESC)

 

그래서 테스트를 위해 각 인덱스는 랭킹 배지, 가장 최근의 챌린지 배지, 연속 읽기 일수가 가장 높은 스트릭 배지를 조회하는 조건과 정렬 순서에 맞춰 설계했습니다. 쿼리 구조를 변경하고 인덱스를 적용한 뒤 다시 EXPLAIN ANALYZE를 실행했습니다.

선제 LIMIT 20과 배지 조회 인덱스를 함께 적용한 실행 계획입니다.

배지 조회 반복 횟수가 1,680회에서 20회로 감소하고 실제 배지 접근에도 인덱스가 사용됐습니다.

실행 계획에서는 내부 서브쿼리의 Limit: 20 row(s)가 배지 조인보다 먼저 실행됐습니다. 이후 세 종류의 배지 조회도 기존 1,680회가 아닌 20회만 반복됐습니다.

 

RANKING 배지는 Index lookup, STREAK 배지는 Covering index lookup을 사용했습니다. CHALLENGE 배지 역시 회원과 카테고리에 해당하는 후보를 인덱스로 조회한 뒤 최신 배지 하나를 선택했습니다.

이때 전체 실행 시간은 약 15.8ms로 측정됐습니다. 운영 로그에서도 인덱스가 적용된 같은 형태의 조회가 60행만 검사한 사례를 확인했습니다.

 

처음에는 충분한 개선이라고 생각했습니다. 하지만 쿼리 실행 순서와 인덱스를 동시에 변경했기 때문에, 실행 시간이 줄어든 핵심 원인이 무엇인지 분리해서 설명하기 어려웠습니다.

선제 LIMIT 20이 대부분의 문제를 해결한 것인지, 세 개의 인덱스도 계속 유지해야 하는지 확인하려면 인덱스를 제거한 상태에서 같은 쿼리를 다시 측정해야 했습니다.

 

인덱스를 제거하고 다시 측정

쿼리 구조는 그대로 유지한 채 배지 조회용 인덱스 세 개를 모두 제거하고 전체 월간 랭킹 쿼리를 다시 EXPLAIN ANALYZE로 확인했습니다.

전체 실행 시간       약 24.8ms
상위 20명 선별       약 11.2ms
배지 3종 조회        약 13.6ms
배지 조회 반복 횟수  각 20회

인덱스를 제거한 실행 계획. 각 배지 조회에서 379행을 스캔하지만, 조회 대상이 상위 20명으로 제한돼 전체 쿼리는 약 24.8ms에 끝났습니다. 인덱스가 없기 때문에 각 배지 조회는 badge 테이블의 379행을 전체 스캔했습니다.

 

379행 × 상위 20명 × 배지 조회 3회 = 최대 22,740회의 행 방문

 

실행 계획의 추정 비용은 크게 표시됐지만, 실제 전체 실행 시간은 약 24.8ms였습니다. 각각의 배지 테이블 스캔도 약 0.17~0.21ms에 끝났습니다.

 

인덱스를 사용했을 때의 15.8ms보다 약 9ms 느려졌기 때문에 인덱스가 전혀 효과가 없었다고 말할 수는 없습니다. 하지만 현재 트래픽과 데이터 규모에서 전체 쿼리 24.8ms는 충분히 작은 비용이었습니다.

세 개의 인덱스를 계속 유지해야 할 정도의 병목이라고 보기도 어려웠습니다. 실행 계획에서 더 많은 행을 읽었다는 사실보다, 실제 쿼리가 서비스의 성능 기준을 만족하는지가 더 중요했습니다.

 

작은 테이블에서는 전체 스캔이 더 빠를 수 있다

쿼리 구조를 개선한 뒤 badge 테이블에는 379행이 있었습니다. 특정 회원이 가진 챌린지 배지는 5행이었고, (member_id, badge_category) 조합당 최대 행 수도 8행에 불과했습니다.

단건 배지 조회의 실행 경로도 별도로 비교했습니다.

정렬까지 지원하는 기존 복합 인덱스  0.665ms
인덱스 없는 전체 스캔              1.28ms
공통 prefix 인덱스 경로            3.35ms

정렬 조건까지 지원하는 복합 인덱스가 가장 빨랐지만, 전체 스캔과의 절대적인 차이는 약 0.6ms였습니다. 반대로 (member_id, badge_category)만 지원하는 공통 인덱스 경로를 강제로 사용한 실험에서는 전체 스캔보다 느린 결과가 나왔습니다.

 

테이블이 작으면 전체 데이터를 순차적으로 읽는 비용이 매우 낮습니다. 보조 인덱스를 탐색한 뒤 원본 행을 다시 읽고, 남은 결과를 정렬하는 비용이 전체 스캔보다 커질 수도 있습니다.

따라서 스캔한 행이 적다는 이유만으로 인덱스 경로가 더 효율적이라고 판단할 수 없습니다. Rows_examined와 실행 계획뿐만 아니라 실제 실행 시간을 함께 확인해야 합니다.

 

이 측정 결과를 바탕으로 기존 인덱스 세 개를 제거하고, (member_id, badge_category) 공통 인덱스로 대체하지도 않기로 했습니다.

공통 인덱스의 설계 자체가 잘못된 것은 아닙니다. badge_category의 값은 세 종류뿐이지만 member_id와 결합하면 충분한 선택도를 가질 수 있습니다. 배지 데이터가 증가한다면 전체 스캔을 줄이는 유효한 선택지가 될 수 있습니다.

 

그러나 현재는 인덱스 없이도 전체 랭킹 쿼리가 약 25ms에 끝났습니다. 아직 발생하지 않은 데이터 증가를 가정해 인덱스를 유지하기보다, 실제 병목이 확인되는 시점에 추가하기로 결정했습니다.

 

인덱스는 비용이 없는 장치가 아니다

인덱스를 추가하면 조회만 빨라지는 것은 아닙니다. 배지가 추가되거나 변경될 때마다 인덱스도 함께 갱신해야 합니다.

이번에 추가했던 세 개의 인덱스는 앞부분 컬럼이 모두 같았습니다.

member_id, badge_category, ...

배지 발급 시 세 개의 B-Tree를 함께 갱신해야 하고, 인덱스 저장 공간도 추가로 필요합니다. 관리해야 할 스키마와 옵티마이저가 검토할 실행 경로도 늘어납니다.

현재 배지 발급량을 고려하면 이 비용이 큰 것은 아닙니다. 하지만 조회 성능 향상이 서비스 관점에서 필요하지 않은 상황이라면, 효과가 확인되지 않은 구조를 계속 유지할 이유도 없었습니다.

이번 결정은 쓰기 비용이 매우 커서 인덱스를 제거했다는 의미가 아닙니다. 현재 데이터 규모에서 얻는 조회 이점이 크지 않았고, 인덱스 없이도 충분한 응답 시간을 확보했기 때문에 더 단순한 구조를 선택한 것입니다.

 

인덱스를 추가해야 할 시점

이번 결정이 badge 테이블에 인덱스가 영원히 필요 없다는 의미는 아닙니다.

상위 20명을 먼저 선택하더라도 인덱스가 없으면 배지 조회마다 전체 badge 테이블을 스캔합니다. 배지 데이터가 증가하면 조회 비용도 선형으로 증가합니다.

배지 1,000행  → 최대 60,000회 행 방문
배지 5,000행  → 최대 300,000회 행 방문
배지 10,000행 → 최대 600,000회 행 방문

따라서 다음 조건 중 하나가 나타나면 인덱스를 다시 검토할 계획입니다.

• 배지 데이터가 5천~1만 행 수준으로 증가한 경우
• 전체 월간 랭킹 쿼리가 지속해서 100ms를 초과하는 경우
• Slow Query나 CPU 사용량에서 배지 스캔이 다시 주요 비용으로 확인되는 경우
• (member_id, badge_category) 조합당 배지 수가 크게 증가한 경우

이때도 처음부터 정렬별 인덱스 세 개를 추가할 필요는 없습니다. 먼저 다음 공통 인덱스를 적용해 전체 테이블 스캔을 줄인 뒤 실행 계획을 다시 확인할 수 있습니다.

CREATE INDEX idx_badge_member_category
    ON badge (member_id, badge_category);

회원과 카테고리 조합당 행 수가 여전히 최대 8행 정도라면, 후보군 안에서 수행하는 정렬 비용은 작습니다. 정렬 컬럼까지 포함한 인덱스는 실제로 정렬이 병목으로 확인됐을 때 추가해도 늦지 않습니다.

 

측정이 설계를 바꿨다

처음 실행 계획을 확인했을 때는 인덱스가 들어가면 좋을 것 같았습니다. 배지 테이블 전체 스캔이 회원마다 반복되고 있었고, 배지 조인이 전체 실행 시간의 약 97%를 차지했기 때문입니다.

하지만 반복 횟수를 1,680회에서 20회로 줄이자 상황이 달라졌습니다. 같은 전체 테이블 스캔도 더는 주요 병목이 아니었습니다.

인덱스의 필요성은 테이블 구조만으로 결정되지 않는다고 생각합니다. 쿼리가 몇 번 반복되는지, 한 번에 몇 행을 확인하는지, 데이터가 얼마나 쌓여 있는지, 실제 실행 시간이 서비스 기준을 만족하는지를 함께 봐야 한다고 생각합니다.

 

쿼리 구조를 먼저 개선하고 같은 조건에서 다시 측정했습니다. 그 결과 현재 데이터 규모에서는 인덱스를 유지하는 것보다 인덱스 없이 단순한 구조를 사용하는 것이 충분하다고 판단했습니다. 향후 배지 데이터와 실행 시간이 실제 기준을 넘는 시점에 다시 측정하고, 그때 필요한 인덱스를 추가할 계획입니다.

 

 

그래도 여전히 문제

이렇게 고쳐도 그대로 동일한 에러가 발생했습니다. 

 

To be continued...