ES /docs

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#

  1. 2026-05-26T12:24:13Z — APM에서 1034ms 지연 감지
  2. 2026-05-26T12:24:16Z — 로그 기록: 요청 완료 (200 OK, 1032.32ms)
  3. 2026-05-26T12:24:17Z — 동일 시간대 다른 호스트에서도 497ms 지연 관측
  4. 2026-05-27 — RCA 분석 완료

Error Log#

Datadog Logs

json
{
  "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: 코드 레벨 결함 없음 — 인프라/런타임 수준 대기 시간
app/controllers/api/v1/admin/editing_entities_controller.rb:8-17ruby
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
app/repositories/editing_entity_repository.rb:83-91ruby
response = ::EditingEntity.search(
  self.query_option.serializable_hash
).paginate(
  per_page: self.query_option.per_page,
  page: self.query_option.page
)

set_response(response)

실행 흐름 분석:

  1. QueryOption::EditingEntity가 params에서 필터 조건 파싱 (page=1, fields 지정)
  2. EditingEntityRepository#_search에서 Elasticsearch bool query 빌드
  3. Elasticsearch 검색 실행 + pagination (total_entries=1, per_page=30)
  4. EditingEntitySerializer로 직렬화 후 응답

기대 동작: 단일 레코드 반환 쿼리로 20-30ms 내 완료 실제 동작: DB/ES 쿼리 6.48ms + serialization 2ms이나 전체 1034ms 소요. 약 1024ms가 request lifecycle의 다른 단계(queuing, middleware, GC)에서 소비됨.

Log Evidence#

사용한 Datadog 쿼리:

text
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):

json
{
  "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):

json
{
  "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) 요청. 코드 결함이 아닌 일시적 인프라 지연으로, 재발 시에만 추가 조치 필요.