50초가 걸리던 페이지의 원인 — t2.micro CPU 크레딧 고갈 추적기

시작하며

토요일 오후, 포케코리아(poke-korea.com)가 느려졌다는 걸 알아차렸다. 정확히는 사용자가 줄어든 걸 먼저 봤다. 분당 10~15명이던 접속자가 5명으로 떨어져 있었다.

확인해 보니 페이지 하나 여는 데 50초가 걸리고 있었다. CloudFront에는 502가 쌓이고 있었고, 백엔드 프로세스는 215번 재시작한 상태였다.

이 글은 그날 장애를 추적한 기록이다. 원인을 찾는 동안 메모리와 소켓, PM2, ALB 설정을 차례로 의심했다. 모두 점검할 이유는 있었지만, 그날 장애가 시작된 이유는 따로 있었다.

운영 환경

먼저 당시 구조를 정리해 둔다.

CloudFront
  │
  ▼
ALB (poke-korea-load-balancing)
  ├─ poke-korea-group  → :80    (Next.js 프론트)
  ├─ api-connect       → :4000  (GraphQL 백엔드)
  └─ poke-docs         → :3001  (Docusaurus 블로그)
  │
  ▼
EC2 t2.micro (1 vCPU / 1GB RAM)
  ├─ PM2로 프론트·백엔드·블로그 3개 프로세스
  ├─ Docker PostgreSQL 2개 (현역 1, 레거시 1)
  └─ 크론 3개 (새벽 시간대)

t2.micro 한 대에 전부 올라가 있다. 2~3년간 별문제 없이 돌아갔기 때문에, 처음에는 인스턴스 사양보다 최근의 코드와 설정 변경을 먼저 의심했다.

첫 번째 확인 — 무엇이 언제 시작됐나

CloudFront 액세스 로그가 S3에 쌓이고 있어서 거기서 출발했다.

gzcat 0829/*.gz | grep -E '"sc-status":"5[0-9][0-9]"' | ...

시간대별 5xx 집계에서 시작 지점이 선명하게 나왔다.

전날 하루 종일 31건이던 5xx가 그날 14,591건이 됐다. 분단위로 좁히니 15시 13분이 시작점이었다.

동시에 몇 가지가 배제됐다.

• 트래픽 급증 아님 — 전날 같은 시간대 23,422건 → 당일 30,512건. 1.3배 수준이다.
• 특정 API 문제 아님 — 폰트(.woff2)와 _next/static 같은 정적 파일까지 502를 맞고 있었다.
• 배포 아님 — 최근 3일간 배포가 없었다.

정적 파일까지 502를 받고 있어 특정 API보다는 오리진 전체의 문제일 가능성이 높았다.

메모리 사용량 확인

가장 먼저 의심한 건 백엔드의 인메모리 캐시였다. 2주 전 러닝셋 조회용 LRU 캐시를 추가했는데, 거기에 상한 설정이 애매한 부분이 있었다.

const MAX_ENTRIES = 2000

const cache = new LRUCache<string, unknown>({
  max: MAX_ENTRIES,
  ttl: ONE_DAY_MS,
  updateAgeOnGet: false,
})

max는 키 개수만 제한한다. maxSize와 sizeCalculation이 없으니 값이 1KB든 50MB든 똑같이 1개로 센다. 게다가 며칠 전 “캐시 단위를 페이지에서 전체 목록으로” 바꾸는 커밋이 있었다. 키 개수는 줄었지만 키 하나의 크기는 폭증하는 변경이었다.

1GB 환경에서 캐시가 수백 MB를 사용한다면 치명적일 수 있었다. 우선 실제 힙 사용량을 확인했다.

Used Heap Size    29.66 MiB
Heap Size         43.57 MiB
Active requests   0

백엔드 힙이 29MB였다. 그리고 dmesg를 뒤져도 OOM Killer 흔적이 없었다.

sudo dmesg -T | grep -iE "killed process|oom-kill|Out of memory: Kill"
# (출력 없음)

Node 힙이 고갈될 때 일반적으로 남는 FATAL ERROR: JavaScript heap out of memory 로그도 없었다. 확인한 시점의 힙 사용량과 로그만으로는 메모리 누수를 원인으로 보기 어려웠다.

CLOSE_WAIT 추적

대신 dmesg에서 다른 게 나왔다.

TCP: out of memory -- consider tuning tcp_mem

커널의 TCP 소켓 버퍼가 고갈됐다는 경고다. 소켓 상태를 보니 심상치 않았다.

391 CLOSE_WAIT
153 ESTABLISHED
 75 LAST_ACK
 55 TIME_WAIT

CLOSE_WAIT은 상대가 연결을 끊었는데 내 애플리케이션이 소켓을 닫지 않은 상태다. 앱이 닫아주지 않으면 커널은 계속 붙들고 있다. 391개면 명백한 누수로 보였다.

백엔드에 graceful shutdown이 없다는 것도 확인했다. SIGTERM 핸들러도, server.close()도, prisma.$disconnect()도 없었다. 215번 재시작하면서 매번 소켓을 흘렸을 거라고 추론했다.

하지만 소켓 소유자를 확인해 보니 백엔드가 아니었다.

CLOSE-WAIT ... [172.31.12.234]:80 ... users:(("PM2 v5.4.3: God",pid=503182,fd=458))

포트가 80이었다. 백엔드는 4000번을 사용하고 있었으므로 조사 대상을 프론트 프로세스로 옮겼다.

PM2 cluster 모드 변경

소유자가 PM2 God 프로세스라는 게 눈에 띄었다. 프론트가 exec_mode: 'cluster'로 돌고 있었기 때문이다.

cluster 모드에서는 PM2의 God 프로세스가 포트를 대신 열고 워커에게 커넥션을 분배한다. 워커가 재시작될 때 God 쪽 fd가 정리되지 않으면 CLOSE_WAIT이 쌓일 수 있다. fd 번호가 458번대까지 올라간 것도 정황에 맞았다.

같은 서버에서 fork 모드로 실행 중인 블로그 프로세스와도 비교했다.

처음에는 exec_mode의 차이가 유의미해 보였다. 다만 후에 확인해 보니 블로그는 트래픽이 거의 없어 조건이 같은 비교 대상이 아니었다.

게다가 이 환경에서 cluster는 이점이 없었다. vCPU가 1개고 instances: 1이라 분배할 대상 자체가 없다. fork로 바꾸고 재기동했다.

CLOSE_WAIT: 391 → 3

이 변경으로 CLOSE_WAIT은 크게 줄었지만 502는 계속됐다.

몇 분 뒤 다시 재보니 숫자가 3 → 24 → 109로 올랐다가 47 → 24 → 3으로 다시 내려갔다. 지속적으로 증가하는 형태는 아니었고, 391개는 재시작 전에 쌓인 연결이었을 가능성이 높았다. PM2 설정은 정리했지만 장애의 원인은 아니었다.

ALB 설정 점검

다음으로 ALB를 봤다. 타겟 헬스 상태가 엉망이었다.

poke-korea-group:  443 unhealthy / 80 healthy
api-connect:      4000 unhealthy  (ResponseCodeMismatch: [400])
poke-docs:        3001 healthy

포트 443에 유령 타겟이 있었다. 아무것도 리스닝하지 않는 포트가 타겟 그룹에 등록돼 있으니, ALB가 그리로 보내는 요청은 전부 502가 된다.

api-connect도 unhealthy였다. 헬스체크 경로가 /인데 GraphQL 서버는 쿼리 없는 GET에 400을 반환한다. 정상 동작인데 ALB는 실패로 판정하고 있었다.

둘 다 실제하는 설정 문제였지만, 그날 장애의 시작 시점을 설명하지는 못했다.

443 타겟은 이전부터 같은 상태였다. 정리해야 할 문제였지만 오늘 갑자기 장애가 시작된 이유로는 볼 수 없었다.

헬스체크 실패도 오리진 응답이 느려진 뒤에 나타났다. ALB 설정보다 오리진의 지연을 먼저 확인해야 했다.

방향 전환 — 실제로 얼마나 느린가

이제 서버 안에서 애플리케이션별 응답 시간을 직접 측정했다.

curl -w "%{http_code} %{time_total}s\n" http://localhost:80/
# 200 37.047410s

curl -w "%{http_code} %{time_total}s\n" http://localhost:80/list
# 200 30.548652s

curl -w "%{http_code} %{time_total}s\n" http://localhost:4000/
# 200 0.473996s

프론트 37초, 백엔드 0.47초. 80배 차이였다.

그런데 잠시 뒤 다시 재보니 더 나빠져 있었다.

list: 49.677678s
champions: 48.872132s

재측정할수록 응답 시간이 늘어났다. 최근 배포가 없었던 점을 같이 고려하면, 시간에 따라 소진되는 자원을 의심할 근거가 됐다.

그리고 top 출력에 이상한 조합이 있었다.

load average: 5.41, 4.05, 3.52
%Cpu(s):  6.2 us,  0.0 sy,  0.0 ni, 93.8 id,  0.0 wa

CPU는 93.8% idle인데 load average는 5.41이었다. vCPU 1개 기준으로 작업이 상당히 밀려 있었다. 처음에는 I/O 대기를 의심했지만 wa는 0.0이었다.

진짜 원인

CloudWatch에서 CPUCreditBalance를 조회했다.

KST 12시   10.31
KST 13시    6.99
KST 14시    3.90
KST 15시    0.08   ← 고갈
KST 16시    0.003
KST 17시    0.0
이후 계속   0.0

15시에 CPU 크레딧이 거의 소진됐고, 502는 15시 13분부터 급증했다.

t2 계열은 버스터블 인스턴스다. 평소에는 baseline(t2.micro는 vCPU의 10%)만 쓰면서 크레딧을 모으고, 부하가 오면 크레딧을 태워 100% 성능을 낸다. 크레딧이 0이 되면 CPU가 baseline으로 강제 제한된다.

93.8 id는 애플리케이션에 CPU 여유가 있다는 의미가 아니었다. 크레딧 고갈로 CPU 사용량이 baseline으로 제한되는 동안, 처리하지 못한 작업이 쌓이고 있었다.

시각상으로는 CPU 크레딧 고갈이 앞서 발견한 현상들을 하나의 흐름으로 설명했다.

이들 중에는 따로 수정해야 할 설정 문제도 있었지만, 15시 13분에 5xx가 급증한 원인은 CPU 크레딧 고갈이었다.

왜 하필 그날이었나

“2~3년 멀쩡했는데 왜 오늘”이 남은 질문이었다. 크레딧 이력을 2주치 뽑아 보니 답이 나왔다.

8월 20일까지는 143으로 만점(144)에 가까웠다. 크레딧이 넘쳐서 더 쌓을 수 없는 상태였다. 그러다 8/22 하루 만에 절반이 날아갔다.

기준선은 **CPU 평균 10%**다. 이 아래면 적립, 위면 소비다. 8/21부터 이 선을 넘기 시작했고, 그때부터 매일 적자였다.

8월 22일에 무슨 일이

CloudFront 로그에서 그날의 상위 IP를 뽑았다.

71,774건  66.249.74.13
30,627건  66.249.74.14
11,558건  66.249.74.15
11,074건  66.249.74.3

66.249.x.x는 Googlebot 대역이다. 날짜별로 집계하니 명확해졌다.

Search Console의 크롤링 통계도 같은 그림을 보여줬다.

하루에 1.4GB를 긁어갔다. 평소의 26배다. SSR로 그만큼의 페이지를 생성하려면 CPU를 계속 태워야 한다.

8/21~22는 사이트에 콘텐츠를 대량 적재한 시점이기도 했다. 포켓몬 도감설명 18,722행을 DB에 넣었는데, 그 직후 구글이 재크롤링을 시작한 것으로 보인다. 다만 이건 정황 추정이다.

크레딧이 문제를 가린 기간

크롤링이 급증한 날의 응답 시간은 오히려 짧았다.

8/20  318ms
8/22  256ms   ← 크롤링 폭주 중인데 더 빠름
8/23  247ms

크레딧이 남아 있는 동안에는 버스트 성능으로 부하를 처리했기 때문에 CPU 사용량 증가가 응답 시간에 바로 드러나지 않았다. 서버는 이미 baseline을 넘어선 상태였지만, 남은 크레딧이 그 징후를 가리고 있었다.

대응

t3.small(2 vCPU / 2GB)로 전환했다. baseline이 vCPU당 20%라 실질 CPU 여력이 4배가 된다.

EBS 볼륨은 그대로 유지되므로 데이터는 보존된다. 확인할 것은 두 가지였다.

• 인스턴스 스토어를 쓰지 않는지 — 쓰고 있다면 중지 시 소실된다
• Docker 재시작 정책 — restart=always가 아니면 수동으로 올려야 한다

둘 다 안전한 상태였다. DB는 bind mount로 EBS 위에 있었고, 컨테이너는 restart=always였다.

# 스냅샷 → 앱 정지 → 인스턴스 중지 → 타입 변경 → 시작
pm2 save
pm2 stop all
docker stop pokemon_db_v2 pokemon_db
sync

결과는 즉각적이었다.

/list 기준으로 응답 시간은 약 500분의 1로 줄었다. 재시작 후 9분 만에 5xx가 0으로 떨어졌고, 실패하던 요청이 정상 처리되면서 분당 요청 수도 195건에서 786건으로 회복됐다.

다음 조사에서 바꿀 점

이번에는 CloudFront 로그와 개별 프로세스를 한참 확인한 뒤에야 CloudWatch를 열었다. 다음에 유사한 전면 지연이 발생하면 장애 시작 시각과 호스트 지표를 먼저 비교하려고 한다.

증상과 원인을 구분하지 않았다

이번에 확인한 CLOSE_WAIT 391개, TCP: out of memory, 헬스체크 실패는 모두 실재하는 현상이었다. 다만 그 현상이 장애 시작 시점을 설명하는지를 먼저 비교했어야 했다.

눈에 띄는 이상 상태를 바로 수정하기보다, 그것이 원인인지 다른 문제로 인한 결과인지를 먼저 확인할 필요가 있었다.

오래된 것과 새로운 것을 구분하지 않았다

443 유령 타겟은 이전부터 같은 상태였다. 정리해야 할 문제였지만 그날 장애의 시작을 설명하지는 못했다.

이후에는 각 현상이 언제부터 존재했는지를 5xx 증가 시점과 함께 비교했다.

사양을 성역으로 뒀다

“2~3년 잘 돌아갔으니 사양은 문제가 아닐 것”이라는 전제가 처음부터 있었다. 그래서 코드와 설정만 뒤졌다.

실제로는 8/20 기준 CPU 평균이 7.8%였다. baseline 10%까지 여유가 2%p뿐이었다. 오래 버텼다는 건 여유가 있다는 뜻이 아니라, 아슬아슬하게 버티고 있었다는 뜻일 수 있다.

지표보다 로그를 먼저 봤다

CloudFront 로그와 ss, dmesg를 한참 판 뒤에야 CloudWatch를 열었다. 그런데 답은 CPUCreditBalance 그래프 하나에 있었다.

로그는 “무슨 일이 일어났는가”를 알려주지만, 지표는 “언제부터 추세가 바뀌었는가”를 알려준다. 원인 불명의 전면 지연에서는 후자가 먼저다.

후속 조치

이번 건과 별개로 정리한 것들이다.

이 중 원인이었던 건 하나도 없다. 하지만 전부 실재하는 결함이었고, 장애를 더 나쁘게 만들거나 진단을 어렵게 한 요소들이다.

특히 알람 부재가 컸다. 사용자가 체감하고 나서야 장애를 알았다. ALB 5xx 알람 하나만 있었어도 15시 13분에 알 수 있었다.

마치며

장애는 8월 29일에 갑자기 드러났지만 CPUCreditBalance는 8월 21일부터 감소하고 있었다. 잔여 크레딧이 부하를 처리하는 동안에는 응답 속도만으로 이 변화를 알기 어려웠다.

이번 장애의 가장 아쉬운 점은 CPU 크레딧 고갈을 늦게 알아챈 것보다, 그 변화를 미리 알려줄 알람이 없었다는 것이다. t2/t3와 같은 버스터블 인스턴스를 운영한다면 CPU 사용률과 함께 CPUCreditBalance도 감시해야 한다.

참고 자료

• Amazon EC2 — Burstable performance instances — 크레딧 적립·소비 메커니즘
• Burstable instances — CloudWatch metrics — CPUCreditBalance, CPUSurplusCreditsCharged 지표
• Amazon EC2 — Change the instance type — 중지 후 타입 변경 절차
• Elastic Load Balancing — Health checks — 헬스체크 임계값과 판정 주기
• Google Search Console — Crawl stats report — 크롤링 요청 수와 다운로드 크기 확인