RCA: Api::V1::PanosController#bulk slow updates (avg 11.7s, max 13.9s)

Overview#

What Happened#

2026-06-24 13:53 KST부터 약 1시간 23분 동안 cupixworks-api 의 PUT /api/v1/panos (Api::V1::PanosController#bulk, bulk_action=update) 요청이 평균 11.7초, 최대 13.9초까지 지연되었다. error-sweeper 가 latency cluster 로 8건을 묶었고, 같은 시간대 Datadog 로그에는 동일 endpoint 의 100건짜리 bulk update 가 us-west-2 / ap-southeast-2 / eu-central-1 세 리전에서 반복적으로 6~11초씩 걸리는 정상 응답이 다수 확인된다. status 는 모두 200 success 로, 에러가 아닌 순수한 latency 이슈다.

Quick Facts#

Affected Teams#

영향 범위는 cupix-agent (User-Agent: cupix-agent) 의 업로드/리뷰 워크플로에서 pano 메타데이터를 일괄 갱신하는 사용자 흐름에 한정된다.

Timeline#

1. 2026-06-24 13:53 KST — error-sweeper 가 Api::V1::PanosController#bulk 의 첫 latency span 을 감지 (first_seen).
2. 2026-06-24 14:53–15:18 KST — us-west-2 의 rogers-obrien / brasfieldgorrie / enbridge tenant 에서 100건짜리 bulk update 가 평균 10초 이상으로 지속 발생.
3. 2026-06-24 15:11–15:18 KST — eu-central-1 (becarabia, hassan-allam) 에서도 동일 패턴.
4. 2026-06-24 15:16 KST — 클러스터 마지막 샘플 (last_seen).
5. 2026-06-24 RCA 시점 — svc:cupixworks-api::unknown 통합 인시던트 (2026-06-24-svc-cupixworks-api--unknown-1) 가 아직 open 상태.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#bulk",
  "service": "cupixworks-api",
  "occurrences": 6,
  "avg_ms": 11717,
  "max_ms": 13912,
  "sample_trace_id": "3513226990505691989"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 8 (cluster) / 동일 시간대 100+ 정상 응답에서도 7초 이상 다수 관찰
• 최초 발생: 2026-06-24 13:53 KST
• 최근 발생: 2026-06-24 15:16 KST

가용성에는 영향이 없으나 (200 OK), 한 호출에 ~10초 이상 걸리면 클라이언트 타임아웃 위험 + Puma worker 점유 시간 증가로 동시 처리량이 떨어진다. 대기 시간 중 ALB/Cloudfront 등 상위 레이어에서 502 가능성도 있다.

Root Cause Summary#

Api::V1::PanosController#bulk 의 bulk_action=update 경로는 BulkableRepository#bulk! 의 per-item 루프에서 한 pano 씩 _repository.update(...) → Pano#save! 를 호출한다. Pano 모델에 include 된 Searchable 및 EntityIndexable concern 은 각 record 의 after_commit on: [:update] hook 에서 Elasticsearch 에 동기 index 요청을 수행하며, 이는 worker 로 비동기 처리되지 않는다. 따라서 한 요청에 100 items 가 오면 같은 request thread 안에서 100 × (DB UPDATE + Pano searchable index + EntityIndexable index + ancestry 조회용 추가 SELECT) 가 순차적으로 실행되어 총 10초대로 누적된다. 로그상 DB 시간(db)은 700–1300 ms 에 불과한 반면 전체 duration 은 9–11초로, ~85–90% 의 시간이 비-DB 동기 외부 호출(주로 Elasticsearch) 에 소비된다는 점이 이를 뒷받침한다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/panos_controller.rb (action bulk 는 BulkableController concern 에서 제공).

def bulk
  _bulked_ids = []
  _invalid_items = []
  case params[:bulk_action]
  when 'create'
    _bulked_ids, _invalid_items = factory_instance.bulk(params, current_user: @current_user, current_team: @current_team, partial_mode: true)
  when 'update', 'delete'
    _bulked_ids, _invalid_items = repository_instance.bulk(params, current_user: @current_user, current_team: @current_team, partial_mode: true)
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'Invalid bulk_action')
  end
  ...
end

핵심 hot loop. update 분기에서 items 를 하나씩 순회하며 per-item repository 를 만들고 update(...) 를 호출한다. 1000건까지 허용되며 (bulk_default_validation!), 실제 운영 트래픽은 대부분 items_count=100 으로 들어온다.

case params[:bulk_action]
when 'update'
  _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))
  rescue StandardError => e
    _invalid_items << { index: index }.merge(Cupix::Util::ErrorParser.parse_error(e))
    next
  end

PanoRepository#update 는 매 호출마다 @model.save! 를 실행하고, 이로 인해 Pano 의 모든 after_commit 콜백이 동기적으로 발화한다.

def update(params = {})
  super

  set_parameters(params)

  begin
    @model.save!
  rescue StandardError => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
  end

  @model
end

Failure point #1 — Searchable 의 동기 ES update. 각 save! 마다 Elasticsearch::Model.client 로 직접 index 요청을 보내며, 실패 시에만 BulkIndexWorker.perform_async 로 fallback 한다. 즉 성공 경로는 항상 동기 호출이다.

after_commit on: [:update] do
  _update_document
end

def _update_document
  Cupix::Logger.debug('begin - _update_document', class: self.class.name, function: __method__)
  if @skip_index_document == true
    Cupix::Logger.debug('end - skip _update_document', class: self.class.name, function: __method__)
    return
  end

  if (attributes_in_database = __elasticsearch__.instance_variable_get(:@__changed_model_attributes).presence)
    # ... synchronous Elasticsearch::Model.client.update(...) on success path ...
  end
rescue Faraday::TimeoutError => e
  Cupix::Logger.error("TimeoutError - #{e.message}", ...)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')  # fallback only on error
end

Failure point #2 — EntityIndexable 가 같은 after_commit on: [:update] 에서 두 번째 동기 ES index 호출을 추가한다. 더 나쁜 점은 as_entity_indexed_json 안의 _entity_ancestry 가 cache 없이 호출되면 매 pano 마다 User / Facility / Capture / Record / Level / Workspace / Team 각각에 대해 추가 SELECT 를 발생시킨다.

included do
  after_commit :_entity_index_document, on: [:create]
  after_commit :_entity_update_document, on: [:update]
  after_commit :_entity_delete_document, on: [:destroy]
end

def _entity_update_document
  return if @skip_index_document == true

  Elasticsearch::Model.client.index(
    index: self.class.entity_index_name,
    id: entity_document_id,
    body: as_entity_indexed_json   # _entity_ancestry 안에서 User/Facility/Capture/Record/Level/Workspace/Team SELECT
  )
rescue StandardError => e
  Cupix::Logger.error("Entity update error - #{e.message}", class: self.class.name, function: __method__)
end

기대 동작: 1000건까지 허용되는 bulk update 는 ES 인덱싱을 worker (BulkIndexWorker.perform_async) 로 위임하여 request 시간을 DB 작업 + queue enqueue 로 한정해야 한다. 실제로 BulkableFactory#bulk! 의 create 경로는 이미 그렇게 처리한다:

unless _skip_valid_ids
  BulkIndexWorker.perform_async(self.class.current_class.name, _new_model_ids, 'index', refresh_cached = false)

  bulk_save_changes_to_partial_json(_new_model_ids.compact)

  run_after_bulk(_new_model_ids, _parent, _items, **kwargs)

실제 동작: update / delete 경로는 per-item save! → after_commit → 동기 ES index 를 100번 직렬 호출. RTT 가 ES 당 ~40-50ms 만 되어도 100건 × 2 콜 = 8–10초가 단순 누적된다.

Log Evidence#

Datadog 쿼리 (재현용):

service:cupixworks-api @http.url_details.path:/api/v1/panos @http.method:PUT

90분 윈도우 (2026-06-24T04:50–06:20Z) 에서 수집한 50건의 요약 — 모두 bulk.action=update, status=success, HTTP 200, db 비율이 10%대.

timestamp                  duration(ms)  db(ms)  items_count  tenant            region
2026-06-24T06:16:39.779Z   11093.56      850.18    100        rogers-obrien     us-west-2
2026-06-24T06:16:51.788Z   10857.05      886.54    100        rogers-obrien     us-west-2
2026-06-24T06:16:04.415Z   10828.05      924.36    100        rogers-obrien     us-west-2
2026-06-24T06:07:55.318Z   10782.27      911.72    100        brasfieldgorrie   us-west-2
2026-06-24T06:13:41.552Z   10649.74      974.77    100        enbridge          us-west-2
2026-06-24T06:13:17.536Z   10511.27      968.50    100        enbridge          us-west-2
2026-06-24T06:18:12.117Z    9811.32     1210.50    100        hassan-allam      eu-central-1
2026-06-24T06:11:13.648Z    9780.33      763.43    100        becarabia         eu-central-1
2026-06-24T06:19:02.263Z    7735.45     1448.16    100        scs-assetfuture   ap-southeast-2
2026-06-24T06:18:38.458Z    9116.95      632.59     91        scs-assetfuture   ap-southeast-2

대표 로그 entry (필드 추출):

{
  "controller": "Api::V1::PanosController",
  "action": "bulk",
  "http": { "method": "PUT", "url_details": { "path": "/api/v1/panos" }, "status_code": 200 },
  "bulk": { "items_count": 100, "action": "update", "status": "success" },
  "duration": 10828.05,
  "db": 924.36,
  "params": { "capture_id": 719254 },
  "team": { "domain": "rogers-obrien", "id": 720 },
  "version": "production-us-west-2-20260624t0540z0-24b9962e-cupixworks"
}

• 90분 윈도우 50건 평균: duration ≈ 7135 ms, items_count ≈ 75, DB 비율 ~12%
• 본 클러스터 자체는 6 sample 평균 11717 ms (items 100 비중이 큼)
• bulk.status 는 전부 success. error log 는 동시간 동일 endpoint 에서 발견되지 않음 → 순수 latency.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 변경 위치: app/repositories/concerns/bulkable_repository.rb:28-58 (update / delete per-item 루프).
• 접근 방식: per-item save! 직전에 _repository.model.skip_index_document! 를 호출해 Searchable 과 EntityIndexable 의 동기 ES index 를 차단하고, 루프 종료 직후 수집된 _model_ids.compact 를 가지고 BulkIndexWorker.perform_async(self.class.current_class.name, _model_ids.compact, 'index') 를 비동기 enqueue 하도록 변경한다. 이는 동일 파일의 bulk_save_changes_to_partial_json 호출(bulkable_repository.rb:71) 과 같은 시점에 자연스럽게 추가 가능하며, factory 의 create 경로(bulkable_factory.rb:61)에서 이미 동일한 패턴이 정착되어 있어 일관성도 확보된다.
• 근거: 로그상 ~85–90% 의 latency 가 비-DB 외부 호출이고, 이를 worker 로 옮기면 100건 update 가 ~1초대로 떨어질 것으로 예상.
• 부수 사실: Searchable#skip_index_document! 는 이미 존재 (searchable.rb:30-32), 그리고 EntityIndexable 도 같은 @skip_index_document 플래그를 사용한다 (entity_indexable.rb:161,173).

단기 개선 (1주 이내)#

• _entity_ancestry 의 추가 SELECT 제거: EntityIndexable 가 _entity_update_document 를 호출할 때 cache 를 전혀 사용하지 않는다 (entity_indexable.rb:172-182). bulk 시나리오에서는 컨트롤러/리포지토리가 capture/facility/team/record/workspace/level 을 한 번에 preload 한 캐시를 모델에 attach 하거나, EntityIndex 도 BulkIndexWorker 와 같이 worker 로 일괄 처리하는 경로를 분리한다.
• BulkableRepository#bulk! 의 update 분기에 enable_bulk_log (Factory 에 이미 있는 패턴, bulkable_factory.rb:142-144 + :55-58) 와 동일한 phase 별 시간 측정 로그를 추가해 회귀 감지.
• Api::V1::PanosController#bulk 트레이싱에 custom span (bulkable.update.item_loop, bulkable.update.es_index) 추가로 어디서 시간이 누적되는지 운영 중에 즉시 확인할 수 있게 한다.

장기 개선 (재발 방지)#

• 모델 콜백에서의 동기 외부 호출 금지 가이드라인 수립: ES, SQS, HTTP, S3 등 외부 호출은 항상 worker 로 위임. 동기 호출이 필요한 곳은 단일 record 컨텍스트로 제한.
• BulkableRepository 의 update/delete 도 factory 의 create 와 동일하게 ActiveRecord::Base.transaction + update_all / insert_all! + 명시적 worker enqueue 패턴으로 통일하여 callback 폭발을 구조적으로 차단.
• Datadog APM 에 Api::V1::PanosController#bulk 의 P95/P99 SLO (예: P95 < 2s) 를 추가하고 회귀 시 알람.

Monitoring#

추가할 메트릭/알림 (release dashboard timeseries widget 용 쿼리):

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

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

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::panoscontroller#bulk}

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

Log 측면 보조 (Logs Explorer measure on @duration, @bulk.items_count):

service:cupixworks-api controller:"Api::V1::PanosController" action:bulk @bulk.action:update @duration:>3000

Alert proposal: Api::V1::PanosController#bulk P95 > 3000 ms for 10 minutes (current baseline 은 ~10초이므로 fix 후 thresholds 재조정).

Risk Assessment#

• Risk level: medium — 사용자 가시 에러는 없으나 100건 단위 일괄 갱신이 평상시 10초 이상 걸려 클라이언트 timeout 및 Puma worker starvation 위험이 존재한다.
• 예상 복잡도: standard — 이미 동일 코드베이스의 BulkableFactory create 경로에서 사용 중인 skip_index_document! + BulkIndexWorker.perform_async 패턴을 update/delete 경로에 옮기는 작업으로, 알고리즘 변경 없이 콜백 회피 + worker enqueue 2줄로 핵심 효과 달성.