RCA: Api::V1::ElementTracesController#refresh latency (avg 27714ms)

Overview#

What Happened#

2026-07-01 07:35 KST 경 cupixworks-api의 PUT /api/v1/element_traces/refresh 요청 하나가 약 27.7초 동안 실행되었다. 요청은 최종적으로 HTTP 200으로 성공했지만 Datadog APM에서 duration > 500ms 기준의 latency outlier로 감지되었다. 원인은 특정 record_id(capture 135047)에 매달린 다수의 ElementTrace를 단일 요청 안에서 하나의 배치로 재색인(Elasticsearch bulk index)하는 동기 처리 경로 때문이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 07:35:25 KST — 동일 서비스에서 svc:cupixworks-api::unknown 인시던트 시작 (2026-06-30-svc-cupixworks-api--unknown-1) — 관련 컨텍스트, 근접 시간대에 다수 클러스터 동시 발생
2. 2026-07-01 07:35:36 KST — 문제의 refresh 요청 시작 (cluster first_seen)
3. 2026-07-01 07:35:39 KST — [DocumentRefreshable][ElementTrace] on {:record_id=>"135047"} batch#1/1 로그 기록 (단일 배치 처리 시작)
4. 2026-07-01 07:36:04 KST — [200] PUT /api/v1/element_traces/refresh 응답 성공 (총 ~27.7s)
5. 2026-07-01 07:36:05 KST — ElementTrace.bulk_operation! 완료 로그 index - id: 128397208 - 128397322
6. 2026-07-01 08:58:01 KST — 관련 svc:* 인시던트 자동 해소

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementTracesController#refresh",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 27714,
  "max_ms": 27714,
  "sample_trace_id": "2948493950061695559"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-01 07:35:36 KST
• 최근 발생: 2026-07-01 07:35:36 KST
• 관찰된 유사 요청: 지난 3일(2026-06-28~2026-07-01) 동안 element_traces/refresh 200 응답이 최소 20건 이상 존재 — 반복 발생 가능성이 있는 만성적 latency

Root Cause Summary#

ElementTracesController#refresh는 요청 파라미터 record_id에 매달린 모든 untrashed ElementTrace를 하나의 HTTP 요청 안에서 동기적으로 재색인한다. DocumentRefreshableRepository#refresh는 find_in_batches(batch_size: 500)로 배치를 나누지만, 각 배치는 ElementTrace.bulk_operation!을 호출해 eager_loaded(includes(element: { bim_revision: :bim }))로 레코드를 로드하고 ElementTraceSerializer로 30개 필드(중첩된 user, team, workspace, facility, deviation, sitetrack, record, element, task, category, phase, workarea 등 포함)를 각 문서마다 직렬화한 뒤 Elasticsearch에 bulk index한다. 문제 요청에서는 record_id=135047(capture)에 대해 다수의 element_trace(id 128397208–128397322)가 단일 배치로 처리되어 총 26초 이상이 소요됐다. HTTP 워커 스레드가 이 시간 내내 점유되므로 응답 latency가 그대로 사용자에게 노출된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/document_refreshable_controller.rb:7-11
• Repository refresh loop: app/repositories/concerns/document_refreshable_repository.rb:5-23
• Bulk index primitive: app/models/concerns/searchable.rb:194-266
• Eager-load scope: app/models/concerns/searchable/element_trace.rb:124-126
• Serializer field list: app/models/concerns/searchable/element_trace.rb:129-168

Controller는 얇은 wrapper로, repository_instance.refresh(params)를 그대로 호출한다:

def refresh
  success = repository_instance.refresh(params)

  render_json success ? 200 : 304, { success: success }
end

Repository의 refresh가 실제 작업을 수행한다. 파라미터로 필터링한 뒤 find_in_batches로 순회하며 배치마다 bulk_operation!을 동기 호출한다:

def refresh(params = {})
  check_refresh_documents(params)

  records = self.class.current_class.untrashed.where(required_parameters(params))
  if params[:per_page].present? && params[:page].present?
    records = records.paginate(page: params[:page], per_page: params[:per_page])
  end

  size = records.size

  records.find_in_batches(batch_size: 500).with_index(1) do |group, batch|
    Cupix::Logger.info("[DocumentRefreshable][#{self.class.current_class}] on #{required_parameters(params)} batch##{batch}/#{size / 500 + 1}")
    self.class.current_class.bulk_operation!(group.pluck(:id))
  end

  true
rescue StandardError => e
  raise e
end

ElementTrace의 required_parameters는 record_id만 사용한다 — 즉 하나의 capture에 매달린 모든 element_trace가 동일 요청에서 재색인된다:

def required_parameters(params = {})
  { record_id: params[:record_id] }
end

def check_refresh_documents(params)
  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'record_id is required') if params[:record_id].blank?
end

bulk_operation!은 매 배치마다 eager_loaded로 다시 로드하고, 각 레코드에 대해 as_indexed_json(=ElementTraceSerializer)를 호출한다. 그리고 결과를 주 index로, 재색인 중이면 tmp_index로도 전송한다:

def bulk_operation!(ids, operation = 'index', refresh_cached = false)
  raise Cupix::Errors::Argument.new(code: 'ARG10000', reason: 'ids is required') if ids.blank?

  batch_for_bulk = []
  if operation == 'delete'
    # ...
  else
    records = self.eager_loaded.where(id: ids)

    records.find_each do |record|
      record.update_all if refresh_cached && record.respond_to?(:update_all) && record.has_attribute?(:cached)
      data_hash = record.as_indexed_json

      case operation
      when 'index'
        batch_for_bulk.push({ index: { _id: record.id, data: data_hash } })
      # ...
      end
    end
  end
  # ...
  begin
    results = self.__elasticsearch__.client.bulk(index: index_name, body: batch_for_bulk)
    # ...
    # NOTE: dual write to tmp_index while reindexing
    if (tmp_index = fetch_tmp_index_name)
      tmp_results = self.__elasticsearch__.client.bulk(index: tmp_index, body: batch_for_bulk)
      # ...
    end
  rescue Faraday::TimeoutError
    raise Cupix::Errors::System.new(code: 'SYS10000', reason: 'Faraday timeout')
  end
end

ElementTrace의 eager_loaded는 element.bim_revision.bim만 preload한다:

def eager_loaded
  includes(element: { bim_revision: :bim })
end

하지만 실제 직렬화는 30개 필드로 매우 넓다 — user, team, workspace, facility, deviation, sitetrack, record, element, task, category, phase, workarea 등 다수의 연관 객체를 문서마다 접근하므로 eager_load에 포함되지 않은 관계는 N+1로 로드될 가능성이 크다:

def as_indexed_json(options = {})
  serializer = ElementTraceSerializer.new(self, {
    is_collection: false,
    fields: {
      element_trace: %i[
        id user team workspace facility deviation sitetrack record
        element task category phase workarea activity_key
        bim_external_id bim_revision_id editing_id texture_id
        vendor status estimated_status cycle_state
        cycle_state_updated_at cycle_state_updated_by
        processing_result purpose created_at updated_at location
      ]
    }
  })

  Searchable.to_searchable_json(self, serializer)
end

기대 동작 vs 실제 동작:

• 기대: refresh는 record_id 필터 하에서 짧게 응답. 대량 재색인 필요 시 백그라운드 worker로 위임.
• 실제: 다수 element_trace 재색인이 HTTP 요청 스레드에서 동기 수행됨. 각 문서 직렬화 + 두 개 index 대상 bulk index로 총 26초 이상 소요.

Log Evidence#

Datadog 쿼리 (trace 단위 재현):

service:cupixworks-api trace_id:2948493950061695559

시간 범위 2026-06-30T22:30:00Z ~ 2026-06-30T22:40:00Z에서 나타난 핵심 이벤트 (KST):

07:35:39 KST  [DocumentRefreshable][ElementTrace] on {:record_id=>"135047"} batch#1/1
07:36:04 KST  [200] PUT /api/v1/element_traces/refresh (Api::V1::ElementTracesController#refresh)
07:36:05 KST  index - id: 128397208 - 128397322  (class=ElementTrace, function=bulk_operation!)

Batch 시작(07:35:39)과 bulk_operation! 완료 로그(07:36:05) 사이 26초 경과, 이는 controller 전체 latency 27.7s와 일치한다. id: 128397208 - 128397322 범위는 단일 배치(=batch_size: 500 이하)임을 시사하지만 정확한 문서 개수는 로그로 확인 불가 (needs verification via DB count).

동일 endpoint의 반복 발생 빈도 확인 쿼리:

service:cupixworks-api "Api::V1::ElementTracesController#refresh" @duration:>10s

지난 3일 동안 20건 이상 반환됨 — 일회성 이벤트가 아니라 만성적 slow path임을 뒷받침한다.

배경 컨텍스트: 문제 요청 직전 다수의 상위 API가 실행되어 element_trace가 대량 생성/갱신되었다 (같은 trace 범위 내):

07:35:32 KST  [200] PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk) (×2)
07:35:36 KST  [200] PUT /api/v1/siteinsights/element_records (Api::V1::ElementRecordsController#bulk)
07:35:38 KST  [200] PUT /api/v1/sitetracks/20465 (Api::V1::SitetracksController#update)
07:36:08 KST  Sitetrack(ID: 20465) processing completed with Capture ID 135047

즉 sitetrack 후처리 완료 직후 element_traces refresh가 호출되는 시퀀스로 보이며, capture당 element_trace 개수가 늘어날수록 latency가 선형 증가함을 의미한다.

관련 svc:* 인시던트 컨텍스트 (status-board):

id: 2026-06-30-svc-cupixworks-api--unknown-1
started_at: 2026-06-30T22:35:25Z (07:35:25 KST)
resolved_at: 2026-06-30T23:58:01Z (08:58:01 KST)
cluster_ids: 8 clusters including 8a18b22e-...

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• APM에서 문제 trace의 span 분해를 확인해 시간 소비 지점(SQL vs Elasticsearch bulk vs serializer)을 정확히 특정한다. Datadog APM trace_id:2948493950061695559를 열어 top spans를 검토.
• 재색인 대상 규모 파악: SELECT COUNT(*) FROM element_traces WHERE record_id = 135047 AND deleted_at IS NULL 로 실제 문서 수 확인 (needs verification).

단기 개선 (1주 이내)#

• 비동기화: DocumentRefreshableRepository#refresh가 임계값 이상의 문서를 다뤄야 할 때 Sidekiq worker로 위임하고, controller는 202/200을 즉시 반환하도록 변경. 응답 계약 변경 여부는 client 호출자 조사 필요 (needs verification).
• eager_load 확장: Searchable::ElementTrace.eager_loaded가 serializer 필드가 참조하는 연관을 모두 커버하도록 includes 그래프를 확장. 최소한 user, team, workspace, facility, deviation, sitetrack, record, task, category, phase, workarea를 preload해 N+1을 제거.
• serializer 슬림화: refresh 경로(Elasticsearch 문서 갱신용)에 한해 얇은 serializer profile을 두어 검색에 실제로 필요한 최소 필드만 직렬화.
• 배치 병렬화: find_in_batches(batch_size: 500)를 유지하되, 배치별로 개별 Sidekiq job에 fan-out해 병렬 처리.

장기 개선 (재발 방지)#

• 이벤트 기반 재색인: after_commit 훅 + 큐 기반 재색인 파이프라인을 도입해 "record_id 전체 refresh" 같은 광범위 재색인 API의 필요성을 제거.
• Zero-downtime reindex 경로 통합: docs/zero_downtime_reindexing_guide.md의 tmp_index dual-write 전략과 refresh 경로가 코드상 분리되어 있으므로 통합해 dual-write cost가 explicit하게 관찰되도록 한다.
• SLO 정의: Api::V1::ElementTracesController#refresh의 P99 latency SLO(예: 2s)를 정하고 초과 시 자동 알림.

Monitoring#

Datadog dashboard에 다음 timeseries widget을 추가한다.

Api::V1::ElementTracesController#refresh P95 latency:

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::elementtracescontroller#refresh}

Api::V1::ElementTracesController#refresh 초당 요청 수:

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

Refresh 요청 에러율:

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::elementtracescontroller#refresh}.as_rate()

ElementTrace.bulk_operation! 실패 로그 카운트 (facet 기반 지표가 없다면 monitor로 대체 — needs verification):

sum:cupixworks-api.logs.bulk_index_failure{service:cupixworks-api}.as_count()

Risk Assessment#

• Risk level: medium — 단일 요청 200 성공이므로 즉시 데이터 손실은 없으나, 27s 동기 응답은 upstream(sitetrack 후처리) 파이프라인을 블로킹하고 HTTP worker 고갈 위험을 초래한다. 지난 3일 20건 이상 관측되어 만성적이며 capture당 element_trace 수 증가에 따라 악화될 수 있다.
• 예상 복잡도: standard — Sidekiq worker 위임 + eager_load 확장은 표준 리팩토링 범위. 동기 → 비동기 응답 계약 변경 시 클라이언트 조율 필요.