RCA: Api::V1::ElementsController#index latency spike (26130ms)

Overview#

What Happened#

2026-07-01 07:43 KST (production us-west-2)에 Api::V1::ElementsController#index 한 건이 26.1초 동안 처리되었다. 동일 facility(umphr6) 사용자가 per_page=300으로 38페이지 분량(11,244 elements)을 페이지네이션으로 순회하던 도중 page 34가 outlier로 지연되었으며, 같은 시각 동일 host(ip-10-1-19-190)에서 PanosController의 bulk/create/check_uploading 요청이 대량으로 발생해 Puma worker 가 혼잡 상태였다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 07:42:13 KST — 사용자 mhughes@pcl.com 가 facility umphr6 element 목록을 per_page=300으로 페이지네이션 시작 (page 14부터 로그 관측). 페이지당 0.4–3초로 정상 처리.
2. 2026-07-01 07:42:41 KST — page 34 요청이 host ip-10-1-19-190 에 도달 (duration 26090ms 역산).
3. 2026-07-01 07:42:53 KST — 같은 cluster에서 PanosController#create/bulk/check_uploading 요청 폭증 시작 (수십 건이 5–16초 소요).
4. 2026-07-01 07:43:07 KST — page 34 요청 완료 (200 OK, 26089ms). cluster file의 last_seen 기준 시각.
5. 2026-07-01 07:43:08–07:43:17 KST — page 35–38 요청은 다시 0.4–2.5초로 회복.
6. 2026-07-01 07:48–07:49 KST — PanosController bulk/index가 본격적으로 느려져 40–109초 소요 (별도 cluster들로 status board incident 2026-06-30-svc-cupixworks-api--unknown-1 의 후속 이벤트로 분류됨).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 26130,
  "max_ms": 26130,
  "sample_trace_id": "8674831959568864694"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-01 07:42 KST
• 최근 발생: 2026-07-01 07:42 KST

요청은 200 OK로 성공했으나, 클라이언트 입장에서 26초 대기. 동일 사용자/세션의 다른 페이지는 정상 응답했고 다른 facility의 element 조회에는 영향 없음. 다만 같은 시각 동일 호스트에서 PanosController 트래픽이 폭증하기 시작했고, 6분 뒤(07:48 KST 이후) 같은 서비스의 다수 endpoint가 40–100초대까지 지연되며 service-level degradation incident로 확산됨 (status board 동일 incident에 5개 cluster 그룹됨).

Root Cause Summary#

해당 26초 latency 는 ElementsController#index 코드 자체의 결함이 아니라, 동일 Puma worker host 의 동시 부하 급증에 따른 처리 지연이다. 슬로우 요청의 내역을 보면 DB 1.7s + Serialization 2.5s 로 코드 경로상의 작업 시간은 4.2s 수준에 불과하고 나머지 22s 는 Puma queue wait 또는 GC pause 로 추정된다 (Datadog request 로그의 duration 은 Rails dispatch 진입응답 시점 사이의 wall time). 같은 시각 host ip-10-1-19-190 에서 PanosController#create / #bulk / #check_uploading / #index 가 동시에 수십 건 인입되어 5–24초씩 처리되고 있었고, 이 부하가 ElementsController page 34 요청과 시간적으로 정확히 겹친다. page 34 만 outlier 가 된 이유는 해당 요청이 도착한 순간 worker pool 이 panos 업로드 처리 로 점유되어 있었기 때문이다.

추가로, ElementRepository#search_by_database 와 _pagination_total 은 페이지마다 response.to_sql(LIMIT/OFFSET 포함)을 캐시 키로 사용하기 때문에 페이지마다 별도의 COUNT 쿼리가 실행된다. 단일 요청 기준으로는 영향이 크지 않지만 (정상 페이지의 db 시간이 200–300ms), worker contention 상황에서 추가 DB round-trip 한 번이 latency 의 변동성을 키우는 부차적 요인이 된다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/elements_controller.rb:13 (Api::V1::ElementsController#index).

def index
  element_query_option = Cupix::QueryOption::Element.new(get_query_option, params)
  elements = repository_instance.search(element_query_option)

  render_api Renderable.new({
    search_result: elements,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

record_id 가 없는 일반 element 목록 조회이므로 query_method 가 :database 를 반환하고 search_by_database 가 호출된다.

def search(query_option = nil)
  set_query_option(query_option)
  # ...
  if query_method(self.query_option) == :elasticsearch
    search_by_elasticsearch(visibility)
  else
    search_by_database(visibility)
  end
end

DB 경로에서 default_joins 는 단순 select 이며 무거운 permission_joins 는 사용되지 않는다.

def search_by_database(visibility)
  # ...
  response = self.class.default_joins(self.class.current_class.visibility_scope(visibility))
  response = response.where(facilities: { key: self.query_option.facility_key || @review.facility.key })
  # ... where(bim_id / category_id / level_id) ...
  response = response.paginate(per_page: self.query_option.per_page, page: self.query_option.page)

  pagination_total = _pagination_total(response)
  SearchResult.new({ contents: response, pagination: pagination_total.merge({...}) })
end

_pagination_total 의 캐시 키에는 paginate 후의 SQL(LIMIT/OFFSET 포함) 이 들어가므로 페이지마다 캐시 미스가 발생해 COUNT 쿼리가 매 페이지마다 실행된다.

def _pagination_total(response)
  Rails.cache.fetch({
    cached_pagination_total: {
      sql: response.to_sql,                                       # paginate 된 SQL이라 페이지마다 키 다름
      t: _cached_total_entries_timestamp(self.query_option.facility_key || @review.facility.key)
    }
  }, expires_in: 4.hours) do
    { total_entries: response.total_entries, total_pages: response.total_pages }
  end
end

Failure point: 외부 부하. ElementsController 자체에는 버그 없음. 본 cluster의 latency 는 동일 host 의 다른 endpoint (PanosController#create/bulk/check_uploading/index) 트래픽 폭증으로 worker 가 점유된 결과.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "ElementsController#index" @duration:>15000

시간 범위 2026-06-30T22:00:00Z – 2026-06-30T23:30:00Z. 결과 1건.

문제의 slow request 원본 로그(요약):

{
  "@timestamp": "2026-06-30T22:43:07.155Z",
  "request_id": "66551ef5-e664-46c7-858f-7163bd3fe81e",
  "host": "ip-10-1-19-190.us-west-2.compute.internal",
  "controller": "Api::V1::ElementsController",
  "action": "index",
  "http": { "status_code": 200, "method": "GET", "url_details": { "path": "/api/v1/elements" } },
  "duration": 26089.93,
  "db": 1729.1,
  "view": 0.12,
  "serialization": { "duration": 2521 },
  "pagination": { "per_page": 300, "current_page": "34", "total_pages": 38, "total_entries": 11244, "previous_page": 33, "next_page": 35 },
  "params": { "facility_key": "umphr6", "per_page": "300", "page": "34", "fields": ["id","bim_external_id","...","custom_properties","bim_bounds","cycle_state","cycle_state_updated_reason"] },
  "user": { "id": 49120, "email": "mhughes@pcl.com", "team": { "id": 739 } },
  "team": { "domain": "pclconstruction", "id": 739 }
}

같은 facility/user 의 인접 페이지 latency (정상):

ts                          dur(ms)    db(ms)   serialization(ms)   page
2026-06-30T22:42:31.037Z    2266.44    330.61   955                 26
2026-06-30T22:42:33.042Z    2484.69    266.66   1714                27
2026-06-30T22:42:35.047Z    1701.62    317.18   912                 29
2026-06-30T22:42:39.059Z    1401.46    257.16   668                 32
2026-06-30T22:42:39.780Z    1227.34    294.88   669                 33
2026-06-30T22:43:07.155Z   26089.93   1729.10   2521                34   ← outlier
2026-06-30T22:43:07.867Z     383.41    206.41   255                 35
2026-06-30T22:43:07.869Z     710.56    313.06   401                 36
2026-06-30T22:43:13.178Z    2539.42    334.72   1688                37
2026-06-30T22:43:17.187Z    1578.29    340.65   665                 38

page 34 의 시작 시각(완료 시각 – duration ≈ 22:42:41.066Z) 직후 같은 host ip-10-1-19-190 에서 PanosController 부하 폭증:

service:cupixworks-api @duration:>5000  (22:35–22:43)

ts                          dur(ms)    db(ms)    controller                   action
2026-06-30T22:42:53.124Z    7375.02    1228.20   Api::V1::PanosController     create
2026-06-30T22:42:55.125Z    6919.10    653.55    Api::V1::PanosController     create
2026-06-30T22:42:55.126Z    6255.12    453.90    Api::V1::PanosController     check_uploading
2026-06-30T22:42:55.126Z    9255.07    954.95    Api::V1::PanosController     create
2026-06-30T22:42:55.126Z   16349.60    905.43    Api::V1::PanosController     index
2026-06-30T22:42:57.131Z   13202.97    1011.35   Api::V1::PanosController     index
2026-06-30T22:42:59.137Z   15431.94    947.17    Api::V1::PanosController     index
2026-06-30T22:42:59.139Z   24192.76    958.61    Api::V1::PanosController     index

이후 service-wide 로 확산:

ts                          dur(ms)     db(ms)    controller                  action
2026-06-30T22:48:14.111Z    43681.90   10983.98   Api::V1::PanosController    bulk
2026-06-30T22:48:14.112Z   109012.31   12338.68   Api::V1::PanosController    bulk
2026-06-30T22:48:34.184Z    81756.59   12501.47   Api::V1::PanosController    bulk

Status board 결과: 같은 incident 2026-06-30-svc-cupixworks-api--unknown-1 (started 22:35:25Z) 에 5개 cluster (3ce7061c, 8a18b22e, 6633f842, 3580e20c, 0c05ab76) 가 묶여 있음 — 본 cluster 는 그 incident 의 한 증상이다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 코드 변경 불필요. 본 cluster 는 단일 발생이고 응답이 200 OK 로 성공한 latency 이벤트이다. 같은 시각의 service-wide degradation 은 이미 status board incident 2026-06-30-svc-cupixworks-api--unknown-1 에 묶여 있으므로, 해당 incident 의 RCA(상위 원인: PanosController bulk/create 폭증) 와 묶어서 처리한다.
• 모니터링 측면에서 Api::V1::PanosController#bulk, #create, #check_uploading 의 동시성/대기 큐를 추적할 alert (아래 Monitoring 섹션) 를 추가한다.

단기 개선 (1주 이내)#

• app/repositories/element_repository.rb:525-537 _pagination_total 의 캐시 키에서 response.to_sql 대신 페이지/오프셋을 제외한 base scope의 식별자(facility_key + 필터 hash) 를 사용하도록 변경해 page 마다 COUNT 가 재실행되지 않게 한다. 현재는 페이지마다 cache miss 가 발생하고 4시간 TTL 도 사실상 무의미하다.
• ElementsController#index 에 per_page 상한(예: 300) 을 명시적으로 enforce 하고 클라이언트가 전 페이지를 순회하는 use case (cupix-agent) 가 있다면 scroll(이미 ScrollableRepository 가 include 되어 있음) 또는 search_after 를 우선 사용하도록 클라이언트 통합을 검토한다.

장기 개선 (재발 방지)#

• Puma worker pool 이 panos 업로드 같은 장기 I/O 작업과 짧은 read API 를 같이 처리하면서 short read 가 큐잉으로 지연되는 패턴이 반복된다. read-heavy endpoint(Elements#index, Panos#index) 와 upload-heavy endpoint(Panos#bulk/#create)를 별도 ASG 또는 별도 puma 프로세스 그룹으로 분리하는 안을 검토한다.
• cupix-agent (User-Agent) 처럼 자동화된 클라이언트가 facility 의 전체 element 를 페이지네이션으로 풀로 끄는 워크플로는 ES 의 search_after / scroll API 또는 server-side cursor 로 전환해 page-wise OFFSET cost 와 COUNT 중복을 제거한다.
• request log 에 Puma queue wait time(X-Request-Start 기반) 을 별도 필드로 노출해 “DB+serialization 이 짧은데 duration 만 큰” 케이스를 자동 분류할 수 있게 한다.

Monitoring#

• ElementsController#index 의 p99 latency:

avg:trace.rack.request.duration.by.resource_service.99p{service:cupixworks-api,resource_name:api::v1::elementscontroller#index}

• Panos bulk/create 의 활성 동시성(상위 원인 endpoint):

avg:trace.rack.request.duration.by.resource_service.95p{service:cupixworks-api,resource_name:api::v1::panoscontroller#bulk}

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::panoscontroller#create}.as_rate()

• Rails request error/slow rate (host 단위로 long-tail 식별):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::elementscontroller#index} by {host}.as_rate()

• DB 누적 시간 (전체 cupixworks-api):

avg:trace.active_record.duration{service:cupixworks-api}

Risk Assessment#

• Risk level: low (단일 발생, 응답 성공, 동일 사용자의 다른 페이지는 정상)
• 예상 복잡도: standard (즉시 조치는 없음. 단기 개선의 _pagination_total 캐시 키 정리는 small/standard scope; 장기 ASG 분리는 critical scope)