RCA: ElementsController#revise Latency (avg 1257ms, max 2828ms)

Overview#

What Happened#

2026-05-27 06:05~06:15 UTC 사이에 cupixworks-api 서비스의 Api::V1::ElementsController#revise 엔드포인트에서 116건의 요청이 평균 1257ms, 최대 2828ms의 응답 시간을 기록했다. 모든 요청은 HTTP 200으로 정상 응답했으나, 각 요청이 100개의 element를 개별 save 호출로 처리하면서 N+1 write 패턴으로 인한 latency가 발생했다.

Quick Facts#

Timeline#

1. 2026-05-27T06:05:57Z — 최초 slow trace 감지 (>500ms threshold)
2. 2026-05-27T06:05~06:15Z — 116건의 revise 요청 연속 발생 (BIM revision 업데이트 batch operation)
3. 2026-05-27T06:15:17Z — 마지막 slow trace 기록

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementsController#revise",
  "service": "cupixworks-api",
  "occurrences": 116,
  "avg_ms": 1257,
  "max_ms": 2828,
  "sample_trace_id": "702067061714033657"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 116
• 최초 발생: 2026-05-27T06:05:57.249Z
• 최근 발생: 2026-05-27T06:15:16.999Z

Root Cause Summary#

revise 메서드가 요청당 최대 100개의 element를 순차적으로 element.save(validate: false) 호출하며 각 save마다 DB write + after_commit 콜백(PubSub publish, DataWareHouse partial JSON 전송)이 개별 실행된다. 100개 element에 대해 100번의 개별 DB UPDATE + 100번의 after_commit 콜백 체인이 직렬로 실행되어 전체 요청 시간이 1~3초에 달한다. Elasticsearch bulk indexing은 마지막에 한 번만 수행되지만, DB save와 콜백 비용이 지배적이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/siteinsights_eventable_controller.rb:16
• Repository dispatch: app/repositories/concerns/siteinsights_eventable_repository/element.rb:7
• DB query (elements load): element.rb:21-22
• Hot loop (N+1 save): element.rb:29-61
• Elasticsearch bulk: element.rb:64-66

def revise
  _revised_ids = repository_instance.revise(params)

  render_json 200, _revised_ids
end

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

  # ... logging for each changed field ...

  update_element_attributes(element, item)
  element.skip_index_document!
  element.event_subject = 'ElementBimRevisionUpdated'
  element.save(validate: false)   # <-- 개별 DB write, after_commit 트리거

  # ... build doc hash for ES bulk ...
  doc
end.compact

각 element.save(validate: false) 호출 시 다음 after_commit 콜백이 실행된다:

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

after_commit :save_partial_json_to_file_as_created, on: :create
after_commit :save_partial_json_to_file_as_updated, on: :update, if: :not_new_record?

skip_index_document! 호출로 Elasticsearch 개별 indexing(Searchable after_commit)은 건너뛰지만, PubSub publish와 DataWareHouse partial JSON 콜백은 여전히 실행된다.

최종적으로 Elasticsearch bulk indexing은 효율적으로 처리된다:

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

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api "elements are considered to be revised"

대부분의 요청이 100개 element를 처리함을 확인:

{
  "timestamp": "2026-05-27 15:15:17",
  "status": "info",
  "message": "100 elements are considered to be revised. element_ids: [16885061, 16885062, ..., 16885160]",
  "class": "Element",
  "function": "revise"
}

{
  "timestamp": "2026-05-27 15:15:19",
  "status": "info",
  "message": "40 elements are considered to be revised. element_ids: [16885261, ..., 16885300]",
  "class": "Element",
  "function": "revise"
}

요청 패턴: 2초 간격으로 연속 요청이 발생. 단일 BIM revision 업데이트 작업에서 수천 개의 element를 100개씩 나누어 revise API를 호출하는 클라이언트 패턴으로 확인됨.

컨트롤러 응답 로그 (모두 HTTP 200):

service:cupixworks-api "ElementsController" "revise"

{
  "timestamp": "2026-05-27 15:15:20",
  "status": "info",
  "message": "[200] PUT /api/v1/elements/revise (Api::V1::ElementsController#revise)"
}

에러/경고 로그 없음:

service:cupixworks-api status:error "ElementsController"  → 0 results
service:cupixworks-api status:warn "ElementsController"   → 0 results

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/concerns/siteinsights_eventable_repository/element.rb:29-61 의 개별 save 루프를 update_all 또는 upsert_all로 대체
• 콜백 실행이 필요한 경우, ActiveRecord::Base.transaction 블록으로 감싸서 commit 횟수를 1회로 줄이기
• DataWareHouse/PubSub 이벤트는 bulk 완료 후 한 번에 발행하는 방식으로 변경

단기 개선 (1주 이내)#

• update_all로 DB 업데이트를 단일 SQL로 처리하고, after_commit 콜백은 bulk 처리 후 별도로 트리거
• import 또는 insert_all/upsert_all (Rails 6+) 활용하여 batch write 수행
• 현재 skip_index_document!처럼 DataWareHouse/PubSub 콜백도 skip 후, bulk 완료 시점에 일괄 발행하는 패턴 적용

장기 개선 (재발 방지)#

• BIM revision 업데이트와 같은 대량 element 수정은 Sidekiq worker로 비동기 처리하여 API 응답 시간에서 분리
• 클라이언트가 1000개 제한까지 한 번에 보내도 응답 시간이 선형 증가하지 않도록 bulk write 패턴을 repository 레벨에서 표준화

Monitoring#

• APM에서 resource_name:Api::V1::ElementsController#revise p95 latency 알림 추가
• Datadog 쿼리:

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::elementscontroller_revise} > 1000

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — 개별 save를 bulk write로 전환하면서 after_commit 콜백 의존 관계를 확인해야 함. 기능 정확성 검증(PubSub event 발행, DataWareHouse sync)이 필요.