RCA: Api::V1::PanosController#update latency spike (41.5s)

Overview#

What Happened#

2026-06-26 10:25 KST 경 cupixworks-api 의 ap-southeast-2 (Sydney) 환경에서 PUT /api/v1/panos/14131203 한 건이 41.485초 동안 처리되었다. 동일 윈도우에서 동일 facility(record_id 14130xxx / 14131xxx) 의 panos 가 대량 동시 생성·수정되는 burst 트래픽이 관측되었으며, 해당 한 건만 outlier 로 잡혀 single-occurrence latency cluster 가 생성되었다. 응답은 200 OK 로 성공했고, 같은 trace 안에서 에러는 없다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-26 10:25:30 KST — 같은 facility 의 panos 가 burst 로 생성/업데이트되기 시작 (POST /api/v1/panos, PUT /api/v1/panos/14130xxx-14131xxx).
2. 2026-06-26 10:25:42 KST (approx.) — PUT /api/v1/panos/14131203 요청 시작 (avg_duration_ms 41485 역산).
3. 2026-06-26 10:25:34 KST — APM span 의 cluster first_seen 타임스탬프 (trace 시작 근처, span 집계 시점).
4. 2026-06-26 10:26:20 KST — 동일 trace 의 Cupix::EventService.publish_event 로그 (Published event - failed_record_count: 0 / 1).
5. 2026-06-26 10:26:23 KST — [200] PUT /api/v1/panos/14131203 (Api::V1::PanosController#update) 완료.
6. 2026-06-26 10:26:55–10:26:59 KST — 직후 Pano/Group/ElementTrace 의 _update_document 가 attributes_in_database 빈 상태로 다수 호출되어 NotFound - attributes_in_database warn 로그 폭증.

Error Log#

Datadog Logs

PUT /api/v1/panos/14131203 (Api::V1::PanosController#update)
status=200 duration=41485ms region=ap-southeast-2 trace_id=3119170903129282850

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-26 10:25:34 KST
• 최근 발생: 2026-06-26 10:25:34 KST

Root Cause Summary#

PUT /api/v1/panos/14131203 요청 한 건이 동일 capture 의 pano 들이 동시에 생성/업데이트되는 burst 트래픽 한가운데에서 처리되면서 약 41.5초가 소요되었다. Api::V1::PanosController#update 의 처리 경로는 repository_instance.update → Pano#save! 후 after_commit 콜백으로 (a) Elasticsearch primary index update, (b) reindex 진행 중이면 tmp_index 에 dual-write, (c) Cupix::EventService.publish_event 를 통한 AWS Kinesis put_records 를 모두 요청 스레드 안에서 동기 호출 한다. burst 시점에 Elasticsearch / Kinesis 의 동시 호출 latency 가 증가하면 모든 외부 콜이 합산되어 단일 요청이 수십 초까지 늘어날 수 있는 구조이며, 본 한 건이 그 outlier 로 잡힌 것이 직접 원인이다. trace 내 에러나 timeout 은 없고, 응답은 200 으로 성공했다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/panos_controller.rb:49-53
• Repository update + save: app/repositories/pano_repository.rb:50-62
• after_commit indexing hook: app/models/concerns/searchable.rb:16-18
• Elasticsearch primary + tmp_index dual write: app/models/concerns/searchable.rb:85-100
• Kinesis put_records (sync): lib/cupix/event_service.rb:21-44

Controller action 은 repository.update 한 줄 + super(render) 뿐이라 컨트롤러 자체 로직은 가볍다.

def update
  @model = repository_instance.update(params)

  super
end

Repository.update 는 @model.save! 만 호출하므로, 비용은 모두 ActiveRecord 콜백 체인에 들어간다.

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

Pano 는 Searchable concern 을 포함해 매 업데이트마다 Elasticsearch primary index 와, 진행 중인 reindex 가 있으면 tmp_index 까지 동기로 update 한다.

unless attributes.empty?
  begin
    request = {
      id: __elasticsearch__.id,
      body: { doc: attributes },
      retry_on_conflict: 5
    }
    request.merge!(type: __elasticsearch__.document_type) if __elasticsearch__.document_type

    results = __elasticsearch__.client.update(request.merge({ index: __elasticsearch__.index_name }))
    Cupix::Logger.debug(results.to_json, class: self.class.name, function: __method__)

    # NOTE: 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
  rescue Elasticsearch::Transport::Transport::Errors::NotFound => e
    Cupix::Logger.warn("NotFound - #{e.message}", class: self.class.name, function: __method__)

    _index_document
  end
end

Kinesis publish 도 요청 thread 에서 동기 호출되며 RestClient/AWS SDK 의 네트워크 RTT 가 그대로 응답 시간에 합산된다.

response = Cupix::Aws::Kinesis.put_records!({ stream_name: stream_name, records: records })
Cupix::Logger.info("Published event - failed_record_count: #{response.failed_record_count} / #{records.size}", class: self.name, function: __method__, event: _event, model: { type: _event.eventable_type, id: _event.eventable_id })

errors = response.records.select { |record| record.error_code.present? } rescue []
if errors.present?
  Cupix::Logger.error("Failed to publish event: #{errors.map(&:error_message).join(', ') rescue nil}", class: self.name, function: __method__, event: _event, model: { type: _event.eventable_type, id: _event.eventable_id })
end

기대 동작: 단일 pano update 가 < 500ms 내에 끝나고, 외부 호출(ES/Kinesis) 이 부하 시에도 일정한 응답 시간을 유지. 실제 동작: 동일 facility 의 panos 가 동시에 update 되며 ES/Kinesis 동시 호출이 누적되어 한 요청이 41.5s 까지 지연. trace 내 모든 외부 호출이 모두 200 으로 성공해 에러는 남기지 않았다.

Log Evidence#

trace 기반 검색 (재현 가능):

service:cupixworks-api trace_id:3119170903129282850

검색 결과 — 같은 trace 안에서 발견된 로그는 정상 처리 흔적뿐이고 에러는 없다.

{
  "timestamp": "2026-06-26 10:26:23",
  "status": "info",
  "message": "[200] PUT /api/v1/panos/14131203 (Api::V1::PanosController#update)"
}

{
  "timestamp": "2026-06-26 10:26:20",
  "status": "info",
  "message": "Published event - failed_record_count: 0 / 1",
  "class": "Cupix::EventService",
  "function": "publish_event"
}

{
  "timestamp": "2026-06-26 10:26:20",
  "status": "info",
  "message": "world_transformation set as [0.6936798954958028, -0.1782751734257641, -0.697872599494311, -28.21095755021309, ...]",
  "class": "Pano",
  "function": "set_world_transformation_from_meta"
}

같은 윈도우(ap-southeast-2) 에서 burst 트래픽 관측 — 같은 facility(Facility 1241) 의 panos 가 동시에 다수 업데이트되었다:

service:cupixworks-api region:ap-southeast-2 status:info
# range: 2026-06-26T01:25:30Z to 2026-06-26T01:26:30Z

샘플 (1초 동안 동일 facility 의 update / mask_upload_url / check_mask_uploading / create 가 수십 건):

10:25:30  POST /api/v1/panos
10:25:30  PUT  /api/v1/panos/14130608
10:25:30  PUT  /api/v1/panos/14131214
10:25:30  PUT  /api/v1/panos/14131213
10:25:30  PUT  /api/v1/panos/14131212
10:25:31  PUT  /api/v1/panos/14131210
10:25:31  PUT  /api/v1/panos/14130602
10:25:31  POST /api/v1/panos/14131211/mask_upload_url
10:25:31  POST /api/v1/panos/14130592/mask_upload_url

직후 (10:26:55–10:26:59 KST) 같은 region 에서 ES 인덱싱 동기 경로의 fallback 로그가 폭증 — 콜백 부하의 흔적이다:

service:cupixworks-api status:warn
# range: 2026-06-26T01:25:00Z to 2026-06-26T01:27:00Z
# 50 hits, NotFound - attributes_in_database (Pano / Group / ElementTrace), function:_update_document

해당 윈도우(01:00Z–02:30Z) 에 대해 tmp_index 관련 active reindex 는 검색되지 않았다 — 즉 활성 reindex 가 원인은 아니다. reindex 활동은 같은 날 더 늦은 시각(예: 10:49–10:50 KST Asset.migrate_data_to_tmp_index!)에 발견되며, 본 요청 시각과 겹치지 않는다.

service:cupixworks-api "tmp_index" (Pano OR Group)
# range: 2026-06-26T01:00:00Z to 2026-06-26T02:30:00Z  → 0 hits

cupixworks-api status:error 같은 윈도우 (01:20Z–01:30Z) 검색 결과는 trace 와 무관한 Cupix::PubSub::Subscribers::UserRecipeGenerator 의 service_jwt private method 에러뿐이며, 이는 facility_permission 이벤트 subscriber 의 기존 이슈로 본 latency cluster 와 직접 연관 증거 없음.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 조치 불필요. 단발성 outlier(occurrence_count=1)이며 응답은 200 으로 성공. burst 가 재현되는지부터 모니터링.

단기 개선 (1주 이내)#

• app/lib/cupix/event_service.rb:21-44 의 Kinesis put_records 호출을 요청 thread 에서 분리. after_commit 안에서 Cupix::EventService.publish_event 를 직접 호출하는 모든 경로를 Sidekiq job (이미 존재하는 BulkIndexWorker 패턴 참고) 으로 비동기화. 200 응답 시간에서 Kinesis RTT 를 제거하면 burst 동안의 tail latency 가 크게 감소한다.
• app/models/concerns/searchable.rb:85-100 의 ES primary update + tmp_index dual-write 도 옵션으로 비동기화 검토. 최소한 tmp_index dual-write 만이라도 진행 중인 reindex 가 있을 때만 별도 worker 로 위임하면, reindex 윈도우에서 burst 트래픽의 동시성을 보호할 수 있다.
• Api::V1::PanosController#update 에 Datadog APM custom span / tagging 을 추가해 ES update, tmp_index update, Kinesis publish 각각의 elapsed 를 분리 측정. 재발 시 어떤 외부 호출이 병목인지 즉시 판단 가능.

장기 개선 (재발 방지)#

• burst 시 요청 단위 단일 record-by-record 처리 대신 client 측에서 bulk_update API(Api::V1::PanosController#bulk_update) 사용 유도. 1 facility 의 panos 수십 건을 1 요청으로 묶으면 ES/Kinesis 호출도 1회로 줄여 동시성 압력이 사라진다.
• ActiveRecord after_commit 콜백에서 외부 시스템(ES/Kinesis/RestClient)을 동기로 부르지 않는 일반 규칙을 정립. 콜백은 perform_async enqueue 만 하도록 코드 가이드라인화.
• Facility 의 cached_entity_updates reset(reset_parent_cached_entity_updates) 가 burst 시 row contention 을 일으키는지 추가 조사 (H4) — 같은 facility 의 다수 자식 row 가 동시에 부모 Facility row 를 갱신하면 PostgreSQL row-level lock 으로 직렬화될 가능성.

Monitoring#

추가 / 강화할 Datadog 쿼리:

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

max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::panoscontroller#update} by {region}

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

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::panoscontroller#update}.as_count() by {region}

p95/p99 latency 가 region=ap-southeast-2 에서 5s 를 넘어가면 알림(threshold 는 widget 외부의 monitor 에서 설정).

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 단발성 outlier 이며 응답은 정상 종료. 재발 빈도(p95/p99 추적) 가 늘어나면 위 단기 개선의 비동기화 작업을 우선순위로 올린다.