Puma — worker thread pool saturation causing request queuing
RCA: EditingEntitiesController#index Latency (1034ms)
Overview#
What Happened#
2026-05-26 12:24:13 UTC에 cupixworks-api 서비스의 Api::V1::Admin::EditingEntitiesController#index 엔드포인트에서 1034ms의 응답 지연이 발생했다. DB 쿼리 시간은 6.48ms에 불과했으며, 전체 1034ms 중 약 1024ms가 애플리케이션 레이어에서 설명되지 않는 대기 시간으로 확인되었다.
Quick Facts#
| Field | Value |
|---|---|
| resource_name | Api::V1::Admin::EditingEntitiesController#index |
| top_frame | app/controllers/api/v1/admin/editing_entities_controller.rb:8 |
| deploy | production-us-west-2-20260526t0459z0-dd7bd097-cupixworks |
| env | production, us-west-2 |
| duration | 1034ms (DB: 6.48ms, serialization: 2ms, view: 0.08ms) |
Timeline#
- 2026-05-26T12:24:13Z — APM에서 1034ms 지연 감지
- 2026-05-26T12:24:16Z — 로그 기록: 요청 완료 (200 OK, 1032.32ms)
- 2026-05-26T12:24:17Z — 동일 시간대 다른 호스트에서도 497ms 지연 관측
- 2026-05-27 — RCA 분석 완료
Error Log#
{
"resource_name": "Api::V1::Admin::EditingEntitiesController#index",
"service": "cupixworks-api",
"occurrences": 1,
"avg_ms": 1034,
"max_ms": 1034,
"sample_trace_id": "499380876619255331"
}
Impact#
- Service:
cupixworks-api - 발생 횟수: 1
- 최초 발생: 2026-05-26T12:24:13.747Z
- 최근 발생: 2026-05-26T12:24:13.747Z
- 영향 범위: 단일 API 요청 (integration@cupix.com, 자동화 클라이언트 Python-urllib/3.11). 사용자 대면 서비스에 직접적 영향 없음.
Root Cause Summary#
요청의 DB 시간은 6.48ms, serialization 2ms, view 0.08ms로 합산 약 8.5ms에 불과하나 전체 응답은 1034ms가 소요되었다. 약 1024ms의 미설명 대기 시간이 존재하며, 이는 Puma worker thread pool 포화로 인한 request queuing 또는 Ruby GC pause가 원인으로 판단된다. 동일 시간대 같은 호스트(ip-10-1-19-190)에서 연속 요청이 132ms, 다른 호스트(ip-10-1-144-228)에서 497ms의 유사한 패턴(DB 시간 대비 전체 시간 격차)이 관측되었으며, 다른 정상 요청들은 17-26ms에 완료되어 일시적인 인프라 수준의 지연 이벤트로 확인된다.
Technical Analysis#
Code Path#
- Entry point:
app/controllers/api/v1/admin/editing_entities_controller.rb:8 - Elasticsearch 검색 실행:
app/repositories/editing_entity_repository.rb:32 - Failure point: 코드 레벨 결함 없음 — 인프라/런타임 수준 대기 시간
def index
editing_entity_query_option = Cupix::QueryOption::EditingEntity.new(get_query_option(enable_current_team: false), params)
editing_entities = repository_instance.search(editing_entity_query_option)
render_api Renderable.new({
search_result: editing_entities,
is_collection: true,
serializer_option: @serializer_option
})
end
response = ::EditingEntity.search(
self.query_option.serializable_hash
).paginate(
per_page: self.query_option.per_page,
page: self.query_option.page
)
set_response(response)
실행 흐름 분석:
QueryOption::EditingEntity가 params에서 필터 조건 파싱 (page=1, fields 지정)EditingEntityRepository#_search에서 Elasticsearch bool query 빌드- Elasticsearch 검색 실행 + pagination (total_entries=1, per_page=30)
EditingEntitySerializer로 직렬화 후 응답
기대 동작: 단일 레코드 반환 쿼리로 20-30ms 내 완료 실제 동작: DB/ES 쿼리 6.48ms + serialization 2ms이나 전체 1034ms 소요. 약 1024ms가 request lifecycle의 다른 단계(queuing, middleware, GC)에서 소비됨.
Log Evidence#
사용한 Datadog 쿼리:
service:cupixworks-api "EditingEntitiesController" (time: 11:24-13:24 UTC 2026-05-26)
service:cupixworks-api @duration:>500 (time: 12:20-12:30 UTC)
service:cupixworks-api status:error (time: 12:00-12:30 UTC)
핵심 로그 — 문제 요청 (1032ms):
{
"host": "ip-10-1-19-190.us-west-2.compute.internal",
"request_id": "300fda90-497f-4873-bef0-a13d7fedae17",
"duration": 1032.32,
"db": 6.48,
"serialization": 2,
"view": 0.08,
"status": 200,
"user": "integration@cupix.com",
"user_id": 36575,
"team_id": 133,
"params": "page=1, fields=[id, entity, cycle_state, record]",
"pagination": "per_page=30, total_entries=1, total_pages=1"
}
동일 시간대 다른 호스트 지연 (497ms):
{
"host": "ip-10-1-144-228.us-west-2.compute.internal",
"request_id": "583244b6-66f2-4e41-a42c-0f39989eaf1b",
"duration": 497.73,
"db": 4.3,
"serialization": 1,
"view": 0.09
}
정상 요청 (동일 시간대): 17-26ms에 완료. 에러 로그 없음.
참고: service:cupixworks-api status:error 쿼리 결과 12:00-12:30 UTC 구간에 에러 로그 0건. 499380876619255331 trace_id는 APM 전용으로 로그에서 미발견.
Hypotheses Considered#
| # | Hypothesis | Evidence for | Evidence against | Verdict |
|---|---|---|---|---|
| H1 | Request queuing (Puma thread pool 포화) | DB 6.48ms vs 전체 1034ms 격차 (~1024ms 미설명); 다중 호스트에서 동시 지연; 정상 요청은 17-26ms | 직접적인 queue depth 로그 없음 | Confirmed |
| H2 | Elasticsearch 쿼리 지연 | Elasticsearch 검색이 주요 I/O 경로 | DB 시간 6.48ms로 정상; total_entries=1로 단순 쿼리 | Rejected |
| H3 | Ruby GC pause | 단일 프로세스 내 대기 시간 설명 가능; 다른 호스트에서도 유사 패턴 | 다른 호스트에서도 동시 발생은 GC 단독으론 설명 불가 | Inconclusive |
| H4 | N+1 쿼리 또는 serialization 과부하 | EditingEntity에 다수 association (level, record, editing 등) | serialization 2ms, view 0.08ms로 정상; 결과 1건 | Rejected |
Fix Recommendation#
즉시 조치 (Critical)#
- 코드 수준 수정 불필요. 이 지연은 애플리케이션 코드 결함이 아닌 인프라/런타임 수준의 일시적 request queuing으로 판단됨.
- 발생 빈도 1회로, 현재 시점에서 즉시 조치할 사항 없음.
단기 개선 (1주 이내)#
- Puma thread pool 설정 검토: 현재 worker/thread 수가 트래픽 피크에 충분한지 확인
- APM에서
@duration:>500ms필터로 해당 엔드포인트의 지연 빈도를 모니터링하여 재발 여부 확인 - request queue time을 별도 메트릭으로 분리하여 queuing vs processing 시간 구분
장기 개선 (재발 방지)#
- Puma queue depth 메트릭을 Datadog에 export하여 thread pool 포화 상황을 사전 감지
- Auto-scaling 정책에 request queue time 기반 트리거 추가 검토
Monitoring#
service:cupixworks-api resource_name:"Api::V1::Admin::EditingEntitiesController#index" @duration:>500ms— 500ms 초과 요청 알림 설정- Puma thread pool backlog 메트릭 대시보드 추가
avg(trace.rack.request.duration){service:cupixworks-api, resource_name:api::v1::admin::editingentitiescontroller#index}— APM 메트릭 모니터
Risk Assessment#
- Risk level: low
- 예상 복잡도: trivial
- 단일 발생 이벤트이며, 사용자 대면 트래픽이 아닌 자동화 클라이언트(Python-urllib) 요청. 코드 결함이 아닌 일시적 인프라 지연으로, 재발 시에만 추가 조치 필요.