Puma 슬롯 고갈 — CPU 21% 인데 502 가 6만 건 난 이유

CPU 도 메모리도 남았는데 Rails 앱이 502 · 504 를 쏟아낼 때 어디를 보면 되는지 정리했다. 다 읽으면 내 앱이 지금 동시에 몇 요청을 받을 수 있는지 계산하고, 오토스케일 조건이 실제로 마르는 자원과 맞물리는지 확인할 수 있다.

결론부터. 병목은 Puma 의 스레드 슬롯이었다. 슬롯은 CPU 도 메모리도 아니라서 계기판 어디에도 안 나왔다.

계기판은 멀쩡했다

메일을 한꺼번에 보낸 직후였다. ALB(AWS 의 로드밸런서)가 50분 동안 502/504 를 62,684건 돌려줬다. 그런데 그래프를 열어 보면 마른 게 없다.

CPU          평상시 1.6%  → 피크 21.3%   (2 vCPU)
메모리       66.5%       → 36.7%
DB 커넥션    10.7        → 13.7         (pool 25)
RDS CPU      4.3%        → 9.7%
응답시간     0.009s      → 2.7s

메모리는 오히려 내려갔다. 오토스케일은 한 번도 안 움직였다. 처음엔 DB 를 의심했는데 RDS 는 10% 도 안 썼다.

5xx 를 둘로 나누니 보였다

ALB 의 5xx 지표는 두 개다. 앱이 돌려준 것(HTTPCode_Target_5XX_Count)과 ALB 가 스스로 만든 것(HTTPCode_ELB_5XX_Count).

Target 5XX                       0
ELB 5XX                     62,684
TargetConnectionErrorCount  19,292

앱은 에러를 하나도 안 냈다. 요청이 앱까지 못 간 거다. TargetConnectionErrorCount 는 ALB 가 백엔드와 연결조차 못 맺은 횟수다. 여기까지 보면 「앱이 바빠서 문을 못 열었다」 로 좁혀진다.

동시 20 으로 초당 296 을 받고 있었다

Rails 앱이 한 번에 처리하는 요청 수는 곱셈 하나로 정해진다.

ECS 태스크 수 × Puma workers × threads

그 프로젝트의 puma.rb 는 WEB_CONCURRENCY · RAILS_MAX_THREADS 로 바꾸게 돼 있었는데, ECS 태스크 정의에 둘 다 없었다. 기본값 2 와 5 가 그대로 들어갔다.

2 tasks × 2 workers × 5 threads = 20

피크는 초당 296 요청. 필요한 동시성은 Little's Law(떠 있는 요청 수 = 초당 요청 × 평균 응답시간)로 바로 나온다. 296 × 2.5초 ≈ 740. 자리 20개에 740 명이 줄을 선 셈이다.

느려지는 걸로 안 끝난 이유 — 헬스체크

슬롯이 다 차면 새 요청은 대기열에서 기다린다. 여기까지는 그냥 느린 거다.

문제는 ALB 헬스체크도 같은 Puma 슬롯을 쓴다는 점이다. 헬스체크가 줄 뒤에서 시간 초과로 떨어지면 ALB 는 그 태스크를 죽었다고 보고 트래픽을 끊는다. healthy host 수(평균)가 1.0 에서 0.1 까지 내려갔다. 보낼 곳이 없으니 ALB 가 5xx 를 직접 만든다. 과부하가 장애로 바뀌는 지점이 여기다.

오토스케일이 못 잡는 구조

스케일 조건은 CPU 80% · 메모리 80% · Sidekiq 큐 300 이었다. 죽은 원인인 스레드 슬롯은 조건에 없다. 정책은 세 개나 붙어 있었고 배선도 맞았다. 감시하는 자원과 마르는 자원이 달랐을 뿐이다. 「설정돼 있다」 와 「작동한다」 는 다른 얘기였다.

CPU 가 21% 에서 멈춘 데도 이유가 있다. Ruby 는 프로세스마다 GVL(한 번에 한 스레드만 Ruby 코드를 돌리게 하는 잠금)이 하나다. 스레드는 I/O 를 기다리는 동안만 자리를 넘긴다. 메일 발송 · 외부 API · 느린 쿼리처럼 기다리는 일이 많으면 슬롯은 꽉 찼는데 CPU 는 논다. 「슬롯 만석 + CPU 21%」 는 I/O 대기형 부하에서 흔히 나오는 모양이다.

그래서 스케일 기준은 TargetResponseTime 이 맞다. 대기열에서 기다린 시간이 ALB 가 재는 응답시간에 들어가기 때문이다. RequestCountPerTarget 은 대신 쓰기 어렵다. 평상시는 10분에 70 요청(응답 0.009초), 장애 때는 10분에 177,514 요청(응답 2.5초)이었다. 같은 요청 수라도 처리 시간에 따라 필요한 슬롯 수가 수백 배 달라진다.

슬롯을 늘리려다 밟을 뻔한 것 — RAILS_MAX_THREADS 는 Puma 만 읽지 않는다

「그럼 RAILS_MAX_THREADS=8 넣으면 되겠네」 가 첫 생각이었다. 넣기 전에 이 변수를 읽는 곳을 찾아보니 Puma 만이 아니었다. Rails 가 만들어 주는 database.yml 도 커넥션 풀 크기를 같은 변수로 정한다. 이 블로그가 돌아가는 저장소도 그렇다.

# config/database.yml
pool: <%= ENV.fetch("RAILS_MAX_THREADS", 5) %>

그 프로젝트는 Puma 와 Sidekiq 를 supervisord 로 한 컨테이너에 띄우고 있었다. ECS 환경변수는 컨테이너 단위라 Sidekiq 프로세스도 같은 값을 받는다.

Puma threads          5 → 8    의도한 것
DB pool              25 → 8    의도 안 한 것
Sidekiq concurrency  10 → 10   sidekiq.yml 에 박혀 있어 그대로
→ Sidekiq 스레드 10개가 커넥션 8개를 다툼 → ConnectionTimeoutError

Puma 만 보면 pool ≥ threads 라 안전해 보인다. 같은 컨테이너의 다른 프로세스까지 봐야 보인다. 그래서 pool 을 DB_POOL_SIZE 같은 전용 변수로 떼어 냈다. 한 변수가 두 역할을 하는 구조가 원인이라, 값만 고치면 또 난다.

배포 순서도 걸린다. terraform apply 는 태스크 정의의 환경변수를 바로 바꾸지만 database.yml 은 이미지 안에 있다. pool 분리 코드가 나가기 전에 apply 하면 그 순간 pool 이 8 이 된다. 인프라와 코드는 다른 길로, 다른 속도로 반영된다. 짝인 변경은 순서를 PR 에 적어 둔다.

내 앱에서 먼저 볼 것

프로덕션 환경변수에 WEB_CONCURRENCY · RAILS_MAX_THREADS 가 실제로 들어가 있는지부터 본다. 기본값으로 돌고 있으면 슬롯 수는 생각보다 작다. Puma.stats(또는 pumactl stats)를 보면 일하는 스레드 수 busy_threads 와 대기열 길이 backlog 가 나온다. 평상시엔 둘 다 거의 0 이라 여유가 넘쳐 보인다. 부하가 왔을 때 무엇이 먼저 마르는지는 미리 계산해 두지 않으면 모른다.

진단 순서표와 workers · threads 비교는 아래 상세에 있다. 「자원은 남는데 5xx」 같은 장애를 겪고 있거나, Rails 를 ECS 에 올리는 구성을 같이 봐 줄 사람이 필요하면 negabaro 에 물어봐도 된다.