ES /docs

ApiController#index (avg 15678ms, max 15678ms)

RCA: ApiController#index 지연 (약 15.7 s)

Overview#

What Happened#

2026-07-25 18:52:03 KST 에 production cupixworks-api 에서 GET / (root) 요청 1건이 15 678 ms 걸려 latency 클러스터로 감지됐다. 해당 엔드포인트는 그저 HTTP 404 를 렌더하는 catch-all 컨트롤러 (ApiController#index) 로 실제 로직이 없다. 같은 30 초 창(window)에서 Api::V1::Admin::StatisticsController#show 가 303 826 ms (약 5분) 동안 실행되며 puma worker 를 점유했고 (83691355-5b5c-4ea2-800c-b04cb6a89ae9 — root_cause_type: resource_exhaustion), 세 클러스터가 함께 incident 2026-07-25-svc-cupixworks-api--unknown-1 으로 묶였다. 즉 본 클러스터는 독립 버그가 아니라 상위 slow-query 인시던트의 victim 이다.

Quick Facts#

Field Value
resource_name ApiController#index
service cupixworks-api
cluster_type latency
avg_duration_ms 15678
max_duration_ms 15678
sample_trace_id 3202199048143534262
env production, us-west-2
tenant cupix

Affected Teams#

Team / Domain Error Count Impact
cupixworks-api (root health probe / crawler) 1 15.7 s 응답 지연. GET / 는 ALB health check, 크롤러, uptime monitor 가 주로 호출하는 경로로 사용자 UX 직접 영향은 낮음. 다만 ALB health check 가 이 경로면 unhealthy 판정 → 트래픽 셰이딩 위험.

Timeline#

  1. 2026-07-25 18:51:34 KST — Api::V1::Admin::StatisticsController#show 슬로우 요청 시작 (관련 cluster 83691355, 303 826 ms).
  2. 2026-07-25 18:51:39 KST — 관련 클러스터 6227ed5a-02f5-4e33-92f2-440dadc62eec 감지 (같은 incident 그룹).
  3. 2026-07-25 18:52:03 KST — 본 클러스터 감지: GET / (ApiController#index) 15 678 ms.
  4. 2026-07-25 18:52:03 KST — incident 2026-07-25-svc-cupixworks-api--unknown-1 자동 resolve (같은 fingerprint 신규 발생 없음).
  5. 2026-07-25 18:56:38 KST — 원인 요청 (StatisticsController#show) 완료 (HTTP 200).

Error Log#

Datadog Logs

text
{
  "resource_name": "ApiController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 15678,
  "max_ms": 15678,
  "sample_trace_id": "3202199048143534262"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1
  • 최초 발생: 2026-07-25 18:52:03 KST
  • 최근 발생: 2026-07-25 18:52:03 KST

Root Cause Summary#

ApiController#index 는 config/routes.rb:4 의 root 'api#index' 에 바인딩된 404 catch-all 이며 컨트롤러 본문은 render status: 404 한 줄뿐이라 정상 서비스 상태에서 수 ms 안에 응답한다. 즉 15.7 s 라는 값은 컨트롤러/DB 로직이 아니라 요청이 puma worker 를 할당받기까지의 대기(queue) 시간으로 대부분 소진되었다고 보는 것이 타당하다. 같은 30 초 창에서 Api::V1::Admin::StatisticsController#show 요청이 303 s 동안 puma worker 1개를 붙잡고 있었고 (83691355-5b5c-4ea2-800c-b04cb6a89ae9 RCA, root_cause_type = resource_exhaustion), 그 동안 초당 1–3건 수준의 GET / health probe 트래픽이 유입되고 있었다 (Datadog [404] GET / (ApiController#index) info 로그 스트림). worker pool 이 슬로우 요청으로 포화되면 후속 짧은 요청은 rack queue 또는 puma request queue 에서 대기하게 되고, 이 큐 대기 시간이 APM trace duration 에 포함된다. 따라서 본 클러스터는 독립 버그가 아니라 상위 slow-query 인시던트 (83691355) 의 victim 이며, StatisticsController#show 를 수정하면 자연 해소된다.

Technical Analysis#

Code Path#

  • Route: config/routes.rb:4 — root 'api#index' 이 / 를 ApiController#index 로 바인딩.
  • Controller entry: app/controllers/api_controller.rb:5-7 — 본문은 단 한 줄 render status: 404.
  • Failure point (실제 지연 발생 지점): 컨트롤러 진입 이전 rack/puma 큐. 컨트롤러 자체는 원인이 아님.
config/routes.rb:3-5ruby
Rails.application.routes.draw do
  root 'api#index'
app/controllers/api_controller.rb:1-8ruby
class ApiController < ApplicationController
  include ClientErrorController
  include ServerErrorController

  def index
    render status: 404
  end
end

기대 동작: render status: 404 만 실행하므로 응답은 수 ms 이내 완료되어야 한다. Datadog 메트릭에서도 동일 리소스의 평상시 duration 은 약 30–40 ms 수준으로 관측된다.

Datadog metric sample (max:trace.rack.request.duration{service:cupixworks-api} by {resource_name})text
0.041377 s  (평상시 값, 약 41 ms)
0.032332 s  (약 32 ms)

실제 동작: trace 3202199048143534262 에서 15 678 ms 소요. 컨트롤러 코드가 이 수준의 지연을 만들 수 없으므로 지연은 컨트롤러 이전 계층 (puma worker wait, rack queue) 에서 발생한 것으로 판단.

Log Evidence#

Datadog query 1 — 본 리소스의 request 로그 (해당 창) 확인:

text
service:cupixworks-api "ApiController#index"
Time: 2026-07-25T09:45:00Z .. 2026-07-25T09:55:00Z

결과: [404] GET / (ApiController#index) info 로그가 초당 1–3 건 밀도로 지속 발생. root path 로의 정기 probe 성 트래픽이 있음이 확인됨. 응답은 모두 404 로 정상 종료.

Datadog query 2 — 동일 창 error 로그:

text
service:cupixworks-api status:error
Time: 2026-07-25T09:45:00Z .. 2026-07-25T09:55:00Z

결과: 0 건. HTTP 500/exception 은 발생하지 않았음 → 코드 예외 경로가 아님을 확인.

Related cluster evidence — 같은 incident 내 최상위 지연 원인:

cluster 83691355-5b5c-4ea2-800c-b04cb6a89ae9 (already RCA'd)json
{
  "resource_name": "Api::V1::Admin::StatisticsController#show",
  "avg_ms": 303826,
  "max_ms": 303826,
  "root_cause_type": "resource_exhaustion",
  "affected_component": "Admin::StatisticRepository#search"
}

83691355 RCA (content/docs/incidents/83691355-5b5c-4ea2-800c-b04cb6a89ae9/rca.mdx:73) 도 본 클러스터를 언급하며 "같은 창에서 ApiController#index 도 15.7 s 지연 — DB/worker 리소스가 함께 눌렸을 가능성" 을 이미 hypothesis 로 남긴 상태.

Incident grouping (bun cli/incident-board.ts for-cluster e341fab5-...):

json
{
  "id": "2026-07-25-svc-cupixworks-api--unknown-1",
  "status": "resolved",
  "started_at": "2026-07-25T09:51:34.302Z",
  "resolved_at": "2026-07-25T09:52:03.330Z",
  "cluster_ids": [
    "83691355-5b5c-4ea2-800c-b04cb6a89ae9",
    "6227ed5a-02f5-4e33-92f2-440dadc62eec",
    "e341fab5-5962-4a91-b6e2-c143a092d5cf"
  ]
}

세 클러스터가 시간창(29 s) 안에서 한 svc-level incident 로 묶였음.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 ApiController#index 자체가 느린 코드 경로 — 컨트롤러 본문은 render status: 404 한 줄 (app/controllers/api_controller.rb:5-7). 평상시 동일 리소스 duration ≈ 32–41 ms (Datadog metric). 15.7 s 를 만들 로직 없음. Rejected
H2 puma worker 포화로 인한 request queue wait — 같은 창 slow query 가 원인 같은 30 s 창에 StatisticsController#show 가 303 826 ms 지속 (83691355 cluster, resource_exhaustion). 세 클러스터가 같은 incident 로 자동 그룹핑 (2026-07-25-svc-cupixworks-api--unknown-1). GET / probe 트래픽이 초당 1–3 건으로 지속 유입되어 대기 큐가 형성될 조건 성립. 큐 대기 시간을 직접 보여주는 puma metric (예: puma.request_backlog, puma.thread_pool.busy) 은 이번 창에서 확보하지 못함 — uncertain, needs verification. Confirmed (primary)
H3 DB connection pool 고갈로 컨트롤러 진입 후 AR connection wait AR connection 은 ApiController#index 경로에서 사용되지 않음 (컨트롤러가 DB 를 건드리지 않음). 컨트롤러 코드에 DB 호출이 전무. Rejected
H4 GC / VM pause — 15.7 s 는 정상 GC pause 규모를 훨씬 넘어섬. 또한 같은 창에 명확한 다른 원인 (slow query) 이 존재. Rejected
H5 상류 (ALB/네트워크) 지연이 trace duration 에 포함 APM rack trace 는 통상 앱 서버 수신 시점부터 계측 → ALB 지연은 포함되지 않는 것이 일반적. Datadog trace 계측 지점이 puma 도달 후이므로 큐 대기 시간이 포함될 수 있어 H2 가 더 정합. Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • 별도 코드 수정 없음. ApiController#index 는 정상적으로 404 를 반환하는 catch-all 이며 본 latency 는 이 컨트롤러의 버그가 아니다.
  • 상위 원인 Api::V1::Admin::StatisticsController#show (cluster 83691355-5b5c-4ea2-800c-b04cb6a89ae9) 의 fix 를 우선 진행. 그 RCA 의 즉시 조치 항목이 반영되면 본 클러스터도 재발하지 않는다.

단기 개선 (1주 이내)#

  • ALB / uptime monitor 의 health check 경로 확인: / 로 probe 를 보내는 주체가 ALB target-group health check 라면, slow-query 발생 시 이 지연으로 target 이 unhealthy 판정되어 트래픽 셰이딩이 유발될 수 있다. 별도 경량 헬스 엔드포인트 (GET /health_check — config/routes.rb:6 에 이미 정의됨) 로 probe 를 이관하는 것을 검토.
  • puma queue 지표 대시보드화: puma.request_backlog, puma.thread_pool.busy 를 서비스 대시보드에 추가해 slow-query 발생 시 downstream 리소스 (ApiController#index 등) 의 큐 대기가 얼마나 커지는지 시각화.

장기 개선 (재발 방지)#

  • Slow endpoint 격리: Admin::StatisticsController 같이 몇 분 단위로 실행되는 관리 API 를 일반 API 와 같은 puma pool 에서 처리하면, 하나의 슬로우 요청이 서비스 전체 지연으로 번진다. Admin 계열 요청을 별도 puma cluster / 별도 서비스로 분리하거나, Sidekiq 로 비동기화하고 결과를 poll/webhook 으로 전달하는 아키텍처 검토.
  • Puma request timeout 도입: rack timeout (예: rack-timeout gem) 을 도입해 60–120 s 이상 걸리는 요청을 강제 종료 → 단일 요청이 worker 를 5분간 점유하는 시나리오 자체를 차단.

Monitoring#

  • cupixworks-api p95 latency by resource — slow query 재발 시 즉시 감지:
text
avg:trace.rack.request.duration.by_http_status.95p{service:cupixworks-api} by {resource_name}
  • GET / (root) latency — 본 클러스터와 같은 victim 패턴 조기 감지:
text
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:ApiController#index}
  • Puma queue depth (있는 경우) — worker 포화 여부 직접 확인:
text
avg:puma.request_backlog{service:cupixworks-api}
  • 장시간 실행 request count — 5 s 초과 요청 발생률:
text
sum:trace.rack.request.hits{service:cupixworks-api,env:production,@duration:>5s}.as_count()

Risk Assessment#

  • Risk level: low (본 클러스터 단독 관점). 상위 원인이 이미 별도 RCA 로 트래킹 중이며, 본 리소스 자체는 버그가 아님.
  • 예상 복잡도: trivial (본 클러스터 대응) / standard (상위 83691355 fix 는 별개).