RCA: Api::V1::PanosController#bulk Latency (avg 6750ms, max 15978ms)

Overview#

What Happened#

2026-05-26 03:24~06:16 UTC 동안 cupixworks-api의 Api::V1::PanosController#bulk 엔드포인트에서 평균 6750ms, 최대 약 16초의 응답 지연이 4개 리전(ap-southeast-2, us-west-2, eu-central-1, ap-southeast-1)에서 148건 발생했다. 모든 요청은 HTTP 200으로 성공했으나, bulk update 시 아이템당 ~100ms의 순차 처리로 인해 100개 아이템 배치에서 ~10초가 소요되는 구조적 성능 문제이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-05-26T03:24:06Z — 최초 slow trace 감지 (ap-southeast-2)
2. 2026-05-26T05:19:04Z — 최대 지연 관측 (18.8초, ap-southeast-2)
3. 2026-05-26T06:16:10Z — 마지막 slow trace 기록
4. 2026-05-26 — Error-sweeper 클러스터 생성 및 RCA 수행

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#bulk",
  "service": "cupixworks-api",
  "occurrences": 148,
  "avg_ms": 6750,
  "max_ms": 15978,
  "sample_trace_id": "3611086426009172877"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 148
• 최초 발생: 2026-05-26T03:24:06.049Z
• 최근 발생: 2026-05-26T06:16:10.112Z
• 영향 범위: 전체 리전의 bulk pano update 사용자 (주로 100개 아이템 배치 요청 시 ~10초 대기)

Root Cause Summary#

BulkableRepository#bulk! 메서드의 update 루프가 각 아이템을 순차적으로 처리하면서, 아이템마다 model.save! 후 after_commit 콜백으로 동기적 Elasticsearch 인덱스 업데이트 (_update_document)가 실행된다. 이 Elasticsearch HTTP 요청이 아이템당 ~30-50ms를 소비하며, event 생성과 기타 콜백을 합산하면 아이템당 ~100ms가 된다. 100개 아이템 배치에서 이 순차 처리가 누적되어 ~10초의 응답 지연을 유발한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/bulkable_controller.rb:25 — bulk action
• Routing: PUT /api/v1/captures/:capture_id/panos → bulk_action: "update"
• Repository dispatch: app/repositories/concerns/bulkable_repository.rb:28-46 — 순차 루프

핵심 병목 코드:

_models.each_with_index do |model, index|
  _repository = self.class.new(review: _review, current_user: current_user, model: model, parent: _parent)
  _item = params[:items].find { |x| x[:id] == model.id }
  next if _item.nil?

  _repository.clear_fields({ fields: _item[:clear_fields] }, with_save: false) if _item[:clear_fields].present?
  _repository.model.publish if _item[:publish].present? && ActiveRecord::Type::Boolean.new.cast(_item[:publish])
  _repository.model.unpublish if _item[:unpublish].present? && ActiveRecord::Type::Boolean.new.cast(_item[:unpublish])
  _repository.model.skip_siteinsights_event_publish! if _repository.model.respond_to?(:skip_siteinsights_event_publish!)
  _repository.update(_item.except(:id))  # 여기서 save! + after_commit 콜백 실행

각 _repository.update 호출 시 model.save!가 실행되고, commit 후 동기적으로 Elasticsearch 업데이트가 트리거된다:

after_commit on: [:update] do
  _update_document
end

_update_document는 Elasticsearch HTTP API를 동기적으로 호출한다:

def _update_document
  return if @skip_index_document == true

  if (attributes_in_database = __elasticsearch__.instance_variable_get(:@__changed_model_attributes).presence)
    attributes = if respond_to?(:as_indexed_json)
                   # ... field mapping logic ...
                   __elasticsearch__.as_indexed_json.select { |k, v| column_names.include?(k.to_s) }
                 end

    unless attributes.empty?
      request = {
        id: __elasticsearch__.id,
        body: { doc: attributes },
        retry_on_conflict: 5
      }
      results = __elasticsearch__.client.update(request.merge({ index: __elasticsearch__.index_name }))

      # dual write to tmp_index while reindexing
      if (tmp_index = self.class.fetch_tmp_index_name)
        __elasticsearch__.client.update(request.merge(index: tmp_index))
      end
    end
  end
end

Per-item 처리 내역 (총 ~100ms/item):

1. DB save + commit: ~6-14ms
2. Elasticsearch _update_document (동기 HTTP): ~30-50ms
3. Event creation (Eventable::Callbacks): ~10-20ms
4. Counter culture update, cache callbacks: ~10-15ms

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api resource_name:"Api::V1::PanosController#bulk" @duration:>5000000000

로그에서 확인된 핵심 패턴:

{
  "resource_name": "Api::V1::PanosController#bulk",
  "http.method": "PUT",
  "http.status_code": 200,
  "duration": 15613000000,
  "db_time_ms": 1261,
  "bulk.action": "update",
  "bulk.items_count": 100,
  "bulk.status": "success",
  "region": "ap-southeast-2",
  "capture_id": 73165
}

DB time vs Total time 비율 분석:

Total: 15,613ms | DB: 1,261ms (8.1%) | View: 0.14ms | App code: 14,352ms (91.9%)
Total: 12,538ms | DB: 987ms (7.9%) | App code: 11,551ms (92.1%)
Total: 9,591ms  | DB: 643ms (6.7%) | App code: 8,948ms (93.3%)

모든 리전에서 일관되게 DB는 전체 시간의 6-11%만 차지하고, 나머지 89-94%가 application code (주로 Elasticsearch 동기 업데이트)에서 소비된다.

아이템 수와 소요 시간의 선형 관계:

items_count: 1   → duration: 173ms   (~173ms/item)
items_count: 50  → duration: 5,200ms (~104ms/item)
items_count: 100 → duration: 9,969ms (~100ms/item)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/concerns/bulkable_repository.rb:30-39: bulk update 루프에서 skip_index_document!를 호출하여 per-item Elasticsearch 업데이트를 비활성화하고, 루프 완료 후 BulkIndexWorker.perform_async로 일괄 비동기 인덱싱 수행
• 이미 skip_index_document! 메커니즘이 searchable.rb:30-32에 존재하므로 활용 가능

단기 개선 (1주 이내)#

• Elasticsearch bulk API (_bulk endpoint)를 사용하여 100개 문서를 단일 HTTP 요청으로 업데이트하는 방식으로 전환. 현재 100번의 개별 HTTP 요청을 1번으로 줄일 수 있음
• Eventable::Callbacks의 event creation도 bulk insert로 전환하거나 async worker로 위임

장기 개선 (재발 방지)#

• Bulk 엔드포인트 전용 after_commit 콜백 전략 도입: bulk 모드에서는 모든 동기 콜백을 억제하고, 루프 완료 후 일괄 처리하는 패턴을 BulkableRepository 레벨에서 표준화
• items_count에 따른 응답 시간 SLO 설정 및 알림 구성

Monitoring#

• APM 대시보드에 PanosController#bulk p95/p99 latency 위젯 추가
• 아이템당 처리 시간 메트릭 추적: avg_duration / items_count

service:cupixworks-api resource_name:"Api::V1::PanosController#bulk" @duration:>5000000000

• Elasticsearch _update_document 소요 시간을 계측하는 custom metric 추가 검토

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — skip_index_document! 메커니즘이 이미 존재하며, bulk 루프 진입 시 활성화하고 루프 종료 후 일괄 인덱싱으로 전환하는 수정이 핵심