RCA: Api::V1::ElementsController#revise 요청 지연 (avg 18.3s, max 30.0s)

Overview#

What Happened#

2026-08-03 22:34 KST경부터 약 2분 동안 cupixworks-api 의 Api::V1::ElementsController#revise 엔드포인트에서 평균 18.3초, 최대 30.0초의 응답 지연이 5회 관측되었다. 최대 30001ms 는 사실상 프런트/게이트웨이의 30 초 타임아웃에 걸린 값이며, 클라이언트가 요청당 100개까지 element 를 묶어 반복 호출하는 패턴이 원인이다. 각 element 마다 순차 save 와 콜백이 실행되기 때문에 배치 크기가 커지면 응답이 선형적으로 늘어난다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-08-03 22:34:31 KST — #revise 최초 지연 관측 (첫 span)
2. 2026-08-03 22:36:24 KST — 마지막 지연 span (총 5건, 평균 18.3s, 최대 30.0s)
3. 2026-08-03 22:57–22:58 KST — 동일 엔드포인트가 초당 최대 3회 배치 호출되며 100건씩 revise 되는 패턴 재확인 (아래 로그)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementsController#revise",
  "service": "cupixworks-api",
  "occurrences": 5,
  "avg_ms": 18341,
  "max_ms": 30001,
  "sample_trace_id": "137375469669308897"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 5
• 최초 발생: 2026-08-03 22:34 KST
• 최근 발생: 2026-08-03 22:36 KST

Root Cause Summary#

Api::V1::ElementsController#revise (via SiteinsightsEventableController#revise) 는 요청 본문의 items 배열(최대 1000 개)을 순회하면서 element 마다 개별적으로 element.save(validate: false) 를 호출한다. 각 save 는 UPDATE 쿼리 1개와 PubSub::Publisher 의 after_save / after_commit 콜백을 트리거하므로 배치당 왕복 수십~수백 회의 DB round-trip 이 직렬로 쌓인다. 로그상 클라이언트가 한 번에 100 건씩 요청을 보내고 있는데, 이 정도만 되어도 평균 18 초, 최대 30 초(=상류 타임아웃 상한) 까지 응답이 밀린다. 결과적으로 이 엔드포인트는 배치 크기에 대해 O(n) 개 트랜잭션·콜백을 발생시키는 N+1 쓰기 병목 구조다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/elements_controller.rb:1 (Rails route PUT /api/v1/elements/revise)
• Action: app/controllers/concerns/siteinsights_eventable_controller.rb:16-20
• Repository: app/repositories/concerns/siteinsights_eventable_repository/element.rb:7-69 (실제 병목)
• Failure point (latency accumulator): app/repositories/concerns/siteinsights_eventable_repository/element.rb:41 — 루프 안의 element.save(validate: false)
• Callback amplifier: app/models/concerns/pub_sub/publisher.rb:37-44 — save 마다 after_save + after_commit PubSub notification

Controller action 은 얇은 pass-through 다:

def revise
  _revised_ids = repository_instance.revise(params)

  render_json 200, _revised_ids
end

실제 작업은 repository 의 loop 에서 이뤄지며, 배치 크기 상한이 1000 이다:

raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'bim_id is required') if params.blank? || params[:bim_id].blank?
raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'Items is required') if params[:items].blank?
raise Cupix::Errors::Parameter.new(code: 'ARG10009', reason: 'Too many items') if params[:items].size > 1000

핵심 hot loop — element 하나마다 개별 save + Elasticsearch document 조립:

bulk_item = elements.map do |element|
  item = id_item_hash[element.id] || ext_id_item_hash[element.bim_external_id]
  next if item.nil?

  # ... 로그 3~5줄 (조건부) ...

  update_element_attributes(element, item)
  element.skip_index_document!
  element.event_subject = 'ElementBimRevisionUpdated'
  element.save(validate: false)     # ← 배치당 N 회 UPDATE + N 회 PubSub 콜백

  doc = { id: element.id }
  # ... doc 필드 세팅 ...
  doc
end.compact

# Indexing to Elasticsearch (여기 하나는 이미 bulk)
if bulk_item.present?
  self.class.current_class.__elasticsearch__.client.bulk(
    index: self.class.current_class.index_name,
    body: bulk_item.flat_map { |item| [{ update: { _id: item[:id], data: { doc: item.except(:id) } } }] }
  )
end

각 save 는 아래 PubSub 콜백을 필연적으로 유발한다:

after_save do |model|
  model.pub_sub_notifications_manager.prepare_notifications(namespace, model)
end

after_commit do |model|
  model.pub_sub_notifications_manager.publish_notifications(namespace)
  model.pub_sub_notifications_manager.reset_notifications(namespace)
end

기대 동작: 100 건짜리 revise 요청이 배치 UPDATE + 배치 이벤트 발행으로 수백 ms 이내 처리. 실제 동작: 100 건마다 100 회 UPDATE + 100 회 after_save/after_commit + 100 회 notification prepare/publish 가 직렬 실행되어 요청당 10~30 초 소요.

Log Evidence#

Datadog query (재현용, cluster 파일의 URL 그대로):

service:cupixworks-api resource_name:"Api::V1::ElementsController#revise" env:production @duration:>500ms

요청 흐름 로그 — 클라이언트가 배치당 100 건씩 초당 여러 번 revise 호출 중:

2026-08-03 22:58:10 info  100 elements are considered to be revised. element_ids: [18149211..18149310]
2026-08-03 22:58:09 info   70 elements are considered to be revised. element_ids: [18149311..18149380]
2026-08-03 22:58:07 info  100 elements are considered to be revised. element_ids: [18149111..18149210]
2026-08-03 22:58:05 info  100 elements are considered to be revised. element_ids: [18149011..18149110]
2026-08-03 22:58:04 info  100 elements are considered to be revised. element_ids: [18148911..18149010]
2026-08-03 22:58:02 info  100 elements are considered to be revised. element_ids: [18148811..18148910]
2026-08-03 22:58:01 info  100 elements are considered to be revised. element_ids: [18148711..18148810]
2026-08-03 22:58:00 info  100 elements are considered to be revised. element_ids: [18148611..18148710]
2026-08-03 22:57:58 info  100 elements are considered to be revised. element_ids: [18148511..18148610]
2026-08-03 22:57:56 info  100 elements are considered to be revised. element_ids: [18148411..18148510]

Datadog query: service:cupixworks-api "elements are considered to be revised" (24h). element_id 가 100단위로 연속 증가 → 단일 BIM revision 흐름에서 대량 element 를 클라이언트가 100건씩 나눠 호출하는 pattern.

200 응답이지만 지연 — 5xx/timeout 로그 자체는 없음 (프런트 타임아웃은 서버 로그에 남지 않음):

2026-08-03 22:58:12 info [200] PUT /api/v1/elements/revise (Api::V1::ElementsController#revise)
2026-08-03 22:58:10 info [200] PUT /api/v1/elements/revise (Api::V1::ElementsController#revise)
2026-08-03 22:58:08 info [200] PUT /api/v1/elements/revise (Api::V1::ElementsController#revise)
...

Datadog query: service:cupixworks-api "/api/v1/elements/revise" status:error → 0 건. 서버는 정상 200 을 리턴하지만 요청 자체가 30 초 근처까지 밀리고 있음. cluster 의 max_duration_ms: 30001 이 상류(ELB/nginx/클라이언트) 타임아웃 임계와 정확히 일치.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 클라이언트 배치 크기 축소로 임시 완화: 프런트/BIM revision 파이프라인 담당자와 협의해 items 배치 크기를 100 → 20~30 수준으로 줄이면 요청당 처리 시간이 선형으로 감소해 30 초 타임아웃을 피할 수 있다. 서버 코드 변경 없이 즉시 배포 가능. ⚠️ 자동 code-fix 대상 아님 — 프런트 조율 필요.
• 입력 상한 재검토 (app/repositories/concerns/siteinsights_eventable_repository/element.rb:10, items.size > 1000): 현재 코드 구조로는 1000 건 요청이 실질적으로 처리 불가능한데도 접수되고 있다. 배치 상한을 200~300 수준으로 낮추고 초과 시 4xx 를 명확히 리턴하는 방향 검토.

단기 개선 (1주 이내)#

• Loop-내부 save 제거 → bulk UPDATE 로 전환 (app/repositories/concerns/siteinsights_eventable_repository/element.rb:29-61):
  • Element.upsert_all 또는 attribute group 별로 UPDATE ... FROM VALUES (...) 를 사용해 elements 를 한 번의 SQL 로 갱신.
  • Rails callback 이 실행되지 않으므로, ElementBimRevisionUpdated PubSub 이벤트는 명시적으로 한 번씩만 publish 하도록 Cupix::PubSub::Publisher.broadcast_event 를 loop 밖에서 배치 호출하도록 재구성.
  • cycle_state_updated_reason 계산은 in-memory 로 미리 결정해 UPDATE 절에 포함.
• 로그 볼륨 축소: 현재는 element 마다 최대 3 개의 info 로그가 찍혀 100 건 배치당 300 로그. bulk 방식으로 전환 후 배치당 요약 1~2 라인으로 축소.
• APM span 추가: revise 안의 (a) DB update, (b) Elasticsearch bulk, (c) PubSub publish 각각에 Datadog::Tracing.trace custom span 을 붙여 다음 회귀 시 원인 구분을 용이하게.

장기 개선 (재발 방지)#

• 대량 mutation 엔드포인트에 대한 아키텍처 가이드라인: revise 처럼 배치 mutation 을 담당하는 API 는 (1) 반드시 bulk SQL 을 사용하고, (2) 콜백은 loop 밖에서 배치 처리하며, (3) 응답 시간 SLO (예: p95 < 5s) 를 명시하도록 코드 리뷰 체크리스트에 추가.
• 비동기화 옵션: element 수가 임계 초과 (예: >200) 시 자동으로 Sidekiq 잡으로 위임하고 202 Accepted + job_id 를 리턴하는 hybrid 패턴 도입 검토. event_subject = 'ElementBimRevisionUpdated' 는 이미 이벤트 기반이므로 async 화가 자연스럽다.
• 엔드포인트별 latency SLO 모니터: 아래 monitoring 쿼리 참고.

Monitoring#

REQUIRED SUB-SKILL: Datadog release-dashboard timeseries 에 바로 붙일 수 있도록 monitor-only 문법을 배제한 timeseries-safe query 로 작성.

• Revise 엔드포인트 평균/최대 지연:

avg:trace.rack.request{service:cupixworks-api,resource_name:api::v1::elementscontroller#revise} by {env}

max:trace.rack.request{service:cupixworks-api,resource_name:api::v1::elementscontroller#revise} by {env}

• 초당 요청 수 (client 가 얼마나 chunk 로 나눠 부르고 있는지):

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

• 30 초 근처 요청 카운트 (proxy for near-timeout):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::elementscontroller#revise,duration:>25s}.as_count()

정확한 메트릭명은 tesla 리포지토리의 기존 Datadog dashboard 를 참고해 확정 필요 (uncertain — needs verification: 위 메트릭은 Datadog Rails APM 표준 명칭 기준이며, 실제 팀 dashboard 는 trace.rack.request.duration 등 커스텀 metric 을 쓸 수 있음).

Risk Assessment#

• Risk level: medium — 현재 5 건 관측이지만 max 30001ms 가 사실상 상류 타임아웃 상한과 일치. 클라이언트 재시도 시 부하가 곱해질 위험 있음.
• 예상 복잡도: standard — bulk UPDATE 전환 자체는 표준적이나 PubSub 이벤트를 loop 밖에서 배치 발행하도록 재구성해야 하고, 다운스트림(siteinsights) 계약 검증 필요.