RCA: Api::V1::PanosController#create latency (avg 11.6s)

Overview#

What Happened#

2026-06-25 00:04 KST부터 02:43 KST 사이에 cupixworks-api의 Api::V1::PanosController#create 요청이 평균 11.6초 (최대 15.5초)로 느려진 latency 클러스터 26건이 관측되었다. 모든 요청은 HTTP 200으로 정상 응답했고, 같은 시간대에 cupixworks-api 전체 평균 request duration도 평소 0.4–0.7초에서 2.5–4.7초로 동반 상승했다. 동일 시간대에 동일 service::unknown 스코프의 다른 6개 클러스터가 함께 incident 2026-06-24-svc-cupixworks-api--unknown-2로 묶여 있다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-25 00:04 KST — Api::V1::PanosController#create 첫 slow span 발생 (cluster first_seen)
2. 2026-06-25 00:00–00:05 KST (UTC 15:00–15:05) — 서비스 전체 평균 duration 2.77s/2.52s, 요청률 132 req/s (평소 50 req/s) 로 1차 spike
3. 2026-06-25 01:45 KST 부터 — incident 2026-06-24-svc-cupixworks-api--unknown-2 open (다른 클러스터 동시 발생)
4. 2026-06-25 02:35–02:40 KST (UTC 17:35–17:40) — 서비스 전체 평균 duration 2.65s/4.75s 로 2차 spike, CPU 11–12%
5. 2026-06-25 02:43 KST — 본 클러스터 last_seen (마지막 slow span)
6. 2026-06-25 02:59 KST — incident resolved (status board 기록)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11520,
  "max_ms": 11520,
  "sample_trace_id": "7013382042757961038"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 26
• 최초 발생: 2026-06-25 00:04 KST
• 최근 발생: 2026-06-25 02:43 KST

Root Cause Summary#

Api::V1::PanosController#create 자체의 코드 경로에는 회귀가 없다. 동시간대에 cupixworks-api service 전체의 평균 request duration 이 평소 baseline (0.4–0.7s) 대비 5–10배 상승했고, 같은 시각의 요청률이 평소 50 req/s 에서 110–132 req/s 로 2배 이상 spike 했다. CPU 사용률도 11–14%로 동시에 상승했다. PanosController#create 는 단일 트랜잭션 안에서 PanoFactory#create! → parent (Capture) lookup → policy check → model.save! → after_commit ⇒ _index_document (Elasticsearch index) → PanoSerializer 직렬화 (다수 concern include) 라는 비교적 무거운 동기 경로를 따르므로, service-wide 부하 spike 시 Puma worker queueing 과 ActiveRecord/Elasticsearch 커넥션 경합으로 인한 평균 지연 증폭에 가장 민감하게 노출된다. 즉 트래픽 spike + create 경로의 fan-out cost 가 결합한 latency 회귀이며, 단일 컴포넌트의 버그가 아니다.

Technical Analysis#

Code Path#

요청 진입점:

def create
  @model = factory_instance.create!(params)

  super
end

Factory 단계 — 동기적으로 capture lookup, policy 체크, optional video/pano lookup, camera 파라미터 설정, save! 까지 직렬 수행:

def create!(params = {})
  self.model = ::Pano.new

  if params[:capture_id].present?
    self.parent = CaptureRepository.new(current_user: self.current_user).show(params[:capture_id])
  elsif params[:capture].present?
    self.parent = CaptureRepository.new(current_user: self.current_user).show(params[:capture])
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'capture_id is required')
  end

  raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: "Can't create a pano") unless self.parent.pano_creatable?

  self.model.capture = self.parent
  self.model.record  = self.parent.record

  if params[:video_id].present?
    origin = VideoRepository.new(current_user: self.current_user).show(params[:video_id])
  elsif params[:pano_id].present?
    origin = PanoRepository.new(current_user: self.current_user).show(params[:pano_id])
  end
  ...
  super
end

BaseFactory#create! 에서 model.save! — 여기서 ActiveRecord 트랜잭션 + after_commit hook 들이 동기로 실행:

def create!(params = {})
  ...
  begin
    self.model.save!
    self.model
  rescue Elasticsearch::Transport::Transport::Errors::BadRequest => e
    ...
  end
end

Pano 모델은 20개 이상의 concern 을 include 한다. 그중 Searchable 이 after_commit on :create 로 요청 스레드에서 동기로 Elasticsearch index 호출을 수행한다:

after_commit on: [:create] do
  _index_document
end

after_commit on: [:update] do
  _update_document
end

...

def _index_document
  return if @skip_index_document == true

  indexed_json = __elasticsearch__.as_indexed_json
  base_request = {
    id: __elasticsearch__.id,
    body: indexed_json
  }

  results = __elasticsearch__.client.index(base_request.merge(index: __elasticsearch__.index_name))
  ...

  # NOTE: dual write to tmp_index while reindexing
  if (tmp_index = self.class.fetch_tmp_index_name)
    __elasticsearch__.client.index(base_request.merge(index: tmp_index))
  end
rescue StandardError => e
  ...
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

Pano 모델의 concern fan-out (after_commit/after_save 등 콜백 다수 등록):

class Pano < ApplicationRecord
  include CaptureEntity
  include EntityIndexable
  include PanoType
  include SignedContent::Pano
  include Searchable::Pano
  include Resourcable::Pano
  include ::Statable::Pano
  include ::Cyclable::Pano
  ...
  include ::Eventable::Pano
  include Publishable::Pano
  ...

  belongs_to :cluster, optional: true
  belongs_to :origin, polymorphic: true, optional: true
  belongs_to :capture, optional: true
  counter_culture :capture,
                  column_name: proc { |model| model.untrashed? && model.count_candidate? ? 'panos_count' : nil },
                  column_names: { ::Pano.untrashed.count_candidate => :panos_count },
                  execute_after_commit: true

  belongs_to :record, optional: true
  ...

기대 동작: 정상 부하 (50 req/s 부근) 에서는 factory_instance.create! 전체가 ~0.5s 안에 완료되어야 한다.

실제 동작: 트래픽 spike (110–132 req/s) 가 들어온 시점부터 동일 경로가 평균 11.6s, 최대 15.5s 로 늘어났다. 같은 시간대에 service-wide 평균 duration 도 동시에 상승했고 PanosController 만 단독으로 영향을 받은 것이 아니다. 즉 create 경로가 baseline 에서 이미 동기 fan-out (Capture lookup, Elasticsearch index, 다수 concern 콜백) 비중이 크기 때문에, Puma 워커 부족 → 큐 대기 시간 증가 + downstream (Postgres, Elasticsearch) 경합 시 가장 먼저 SLO 경계를 넘어간다.

Reindex / dual-write 상태 (Revision 2 조사)#

searchable.rb:47-49 의 dual-write 분기는 self.class.fetch_tmp_index_name (= Rails.cache.read("searchable:reindex_helper:tmp_index:#{index_name}")) 가 nil 이 아닐 때만 동작한다 (app/models/concerns/searchable/reindex_helper.rb:13-15). 이 키는 오로지 prepare_zero_downtime_reindex! (reindex_helper.rb:21-31) 가 호출될 때만 작성되며, 코드베이스 안에서 이 메서드를 자동 실행하는 worker/rake task/스케줄러는 존재하지 않는다 (Grep 결과: prepare_zero_downtime_reindex 호출은 spec 과 docs 외에 없음). 즉 dual-write 활성화는 운영자가 수동으로 콘솔에서 Model.prepare_zero_downtime_reindex! 를 실행해야만 시작된다.

Datadog 로그 14일 윈도우에서 reindex lifecycle 로그는 0건이다 (prepare_zero_downtime_reindex, Prepared zero-downtime, migrate_data_to_tmp_index, Begin migrating data to tmp_index, promote_tmp_index_to_alias, now points to, halt_zero_downtime_reindex, tmp_index, ReindexHelper 키워드 모두 cupixworks-api/cupixworks-worker 양쪽에서 0건). 본 incident 시점 (2026-06-24 15:00–18:00 UTC) 에도 어떤 모델에서도 reindex prepare/migrate/promote 로그가 발견되지 않았다.

따라서 본 incident 시점에 Pano 모델이 dual-write 모드에 있었다는 증거는 없다. 다른 Searchable 모델 60여 종 (Capture, Record, Group, Facility, Annotation, ... app/models/*.rb 의 include Searchable::*) 도 동일하게 14일간 lifecycle 로그가 없으며, 현재 dual-write 진행 중인 모델은 로그 기준으로 식별되지 않는다. 단 Redis 키 searchable:reindex_helper:tmp_index:* 의 실제 존재 여부는 production Redis 직접 조회가 필요하므로, 코드/로그 만으로 100% 확정할 수는 없다 (오래 전에 prepare! 만 호출하고 promote!/halt! 없이 방치된 경우, Redis TTL 이 nil 이라 lifecycle 로그 없이 키만 남아있을 수 있다).

요약: 본 incident 의 latency 회귀에 dual-write 가 기여했다고 볼 수 있는 증거는 없다. 기존 보고서의 Fix Recommendation 에서 "dual-write tmp_index" 관련 문구는 미래 reindex 작업이 트래픽 spike 와 겹쳤을 때의 위험에 대한 가설로만 유효하며, 현재 상시 비용으로 가산되고 있지 않다.

Log Evidence#

검색에 사용한 Datadog 쿼리 (재현 가능):

service:cupixworks-api "PanosController" "create"
service:cupixworks-api status:error
service:cupixworks-api status:warn
service:cupixworks-api ("timeout" OR "Faraday::Timeout" OR "PG::ConnectionBad" OR "ActiveRecord::ConnectionTimeoutError" OR "slow query")

1) PanosController#create 호출은 모두 200 OK 로 응답 — error/timeout 로그는 0건:

{
  "timestamp": "2026-06-25 02:59:59",
  "status": "info",
  "message": "[200] POST /api/v1/panos (Api::V1::PanosController#create)"
}

service:cupixworks-api status:error (2026-06-24 15:00–18:00 UTC) 검색 결과 4건 — 모두 무관한 BIM360/OPC integration 토큰 갱신 실패 (PanosController 와 무관). 즉 본 클러스터는 5xx error 가 아닌 순수 latency 회귀.

2) 같은 시간대 service 전체 평균 duration 동반 상승 (avg:trace.rack.request.duration{service:cupixworks-api}, 5분 버킷, KST 환산):

2026-06-25 00:00 KST  duration=2.767s   <-- cluster first_seen
2026-06-25 00:05 KST  duration=2.516s
2026-06-25 00:10 KST  duration=0.851s
...
2026-06-25 02:35 KST  duration=2.649s
2026-06-25 02:40 KST  duration=4.746s   <-- 2차 spike 정점
2026-06-25 02:45 KST  duration=1.608s   <-- cluster last_seen 직후
2026-06-25 02:50 KST  duration=1.117s

평소 baseline (해당 24h 윈도우의 다른 시간대) 은 0.3–0.7s. cluster 양 끝에서 baseline 대비 5–10배 상승.

3) 동시간대 요청률 spike (sum:trace.rack.request.hits{service:cupixworks-api}.as_rate()):

2026-06-25 00:00 KST  rate=95.3 req/s
2026-06-25 00:05 KST  rate=132.9 req/s   <-- 평소 ~50 req/s 의 2.5배
2026-06-25 00:50 KST  rate=112.9 req/s
2026-06-25 01:45 KST  rate=116.0 req/s
2026-06-25 02:35 KST  rate=93.1 req/s
2026-06-25 02:40 KST  rate=83.3 req/s

10분 윈도우 (2026-06-24T15:00–15:10 UTC, 2026-06-24T17:35–17:45 UTC) 안에서 PanosController#create 호출 자체가 limit 500을 초과 — pano 생성이 분당 수천 건 수준으로 들어오고 있었다.

4) CPU 동반 상승 (avg:system.cpu.user{service:cupixworks-api}):

2026-06-25 00:00 KST  cpu=11.94%
2026-06-25 00:05 KST  cpu=14.32%   <-- 1차 정점
2026-06-25 02:35 KST  cpu=11.36%
2026-06-25 02:40 KST  cpu=12.12%   <-- 2차 정점

베이스라인 3–6% 대비 2–3배 상승하면서 duration spike 와 같은 5분 버킷에 정렬.

5) NotFound - attributes_in_database warn 로그 — Searchable concern 의 _update_document 에서 발생. on :update 콜백이라 본 클러스터의 :create 경로와는 직접 관련 없으나, 동일 시간대에 Pano/Group 모델에서 다량 발생 → ES 트래픽 자체가 평소보다 많았음을 의미:

{
  "timestamp": "2026-06-25 02:59:58",
  "status": "warn",
  "message": "NotFound - attributes_in_database",
  "class": "Pano",
  "function": "_update_document"
}

증거 위치: app/models/concerns/searchable.rb:108.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 추가 코드 변경 없음: 본 클러스터 단독으로는 hotfix 가 필요한 코드 회귀가 확인되지 않았다. 동일 incident 2026-06-24-svc-cupixworks-api--unknown-2 가 이미 resolved 상태이므로 운영 측면에서는 종결.
• 트래픽 spike 가 다시 들어왔을 때 같은 패턴으로 재발할 가능성이 높으므로, cupixworks-api (Puma) 의 worker/thread 수와 RDS / Elasticsearch 커넥션 풀 capacity 를 incident 기간 (2026-06-24 15:00–18:00 UTC) 사용 패턴으로 capacity check 권장. 변경은 인프라 (terraform / cupix-infrastructure) 측 결정.

단기 개선 (1주 이내)#

• PanoFactory#create! 의 동기 fan-out 줄이기: Searchable._index_document 의 ES index 호출 (app/models/concerns/searchable.rb:34-49) 을 트래픽 부하 상황에서 비동기(BulkIndexWorker.perform_async) 로 우회 가능한지 검토. 현재는 rescue 시에만 fallback. (참고: dual-write 분기는 본 incident 시점에 활성화되어 있지 않았음 — Revision 2 의 reindex 상태 조사 참조. 다만 향후 reindex 작업이 트래픽 spike 와 겹치면 추가 ES write 1회가 더해진다는 위험은 상존)
• Pano 모델의 after_commit 콜백 fan-out (app/models/pano.rb:1-46) 중 클라이언트 응답 latency 에 포함될 필요가 없는 콜백(예: Eventable, Publishable) 을 식별하고 백그라운드 워커로 분리.
• _update_document 의 NotFound - attributes_in_database warn 은 빈 attributes_in_database 일 때 무조건 _index_document 로 폴백하므로 트래픽 spike 시 ES 부담을 가중. early return 또는 빈도 제한 검토 (searchable.rb:108-110).

장기 개선 (재발 방지)#

• 트래픽 spike 시 가장 먼저 SLO 를 깨는 endpoint (Api::V1::PanosController#create) 에 대한 p95/p99 SLO 를 명시하고, write-heavy 경로의 동기 ES indexing 정책을 outbox/async-index 패턴으로 전환하는 아키텍처 결정.
• Pano 업로드 클라이언트(모바일/웹) 의 burst pattern 을 server-side rate limit 또는 client-side jitter 로 평탄화 — 한 capture 의 다중 pano 업로드가 동기 burst 로 들어오는 것이 트래픽 spike 의 주요 원인일 가능성이 높다 (10분에 500+ 건 cap 도달).

Monitoring#

추가하거나 release dashboard 에 고정해야 할 timeseries widget:

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

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

avg:trace.rack.request.duration{service:cupixworks-api}

sum:trace.rack.request.hits{service:cupixworks-api}.as_rate()

avg:system.cpu.user{service:cupixworks-api}

알림 권장 (별도 monitor 로 분리):

• Api::V1::PanosController#create p95 latency > 5s for 5m → warn
• cupixworks-api 전체 avg duration > 2s for 5m → warn (fleet-wide degradation 조기 감지)

Risk Assessment#

• Risk level: medium — 사용자 응답이 11–15초 지연되어 모바일/웹 클라이언트 timeout 및 재시도 폭주 가능. HTTP 5xx 는 발생하지 않았으므로 데이터 손실 없음. 동일 incident 가 2시간 안에 자연 해소됨.
• 예상 복잡도: standard — 코드 변경이 필수가 아니라 인프라 capacity check + 선택적 async indexing refactor. 어느 쪽도 trivial 한 1-line fix 는 아니지만 critical hotfix 도 아니다.

Revision History#

Revision 2#

Feedback: Pano 가 지금 dual-write 진행중이라는 증거가 있는지, 그리고 다른 모델 중 dual-write 진행중인 것이 있는지 확인 요청.

판정:

변경 사항:

• ## Technical Analysis → ### Code Path 끝부분에 #### Reindex / dual-write 상태 (Revision 2 조사) 서브섹션을 추가하여 dual-write 트리거 메커니즘과 14일 lifecycle 로그 부재를 정리.
• ## Hypotheses Considered H3 의 "evidence for" 컬럼에서 dual-write 추가 호출 가설을 제거하고, "evidence against" 컬럼에 14일간 reindex lifecycle 로그 0건 사실을 추가.
• ## Fix Recommendation → 단기 개선 항목에서 "tmp_index dual-write" 표현을 제거하고, 본 incident 시점에는 dual-write 가 활성 비용이 아니었음을 주석으로 명시. Pano 모델 콜백 분리 항목에서도 "Searchable 의 dual-write tmp_index" 예시를 제거.
• Root Cause Summary 직후 동기 fan-out 묘사에서 "dual-write to tmp_index 가능성" 문구를 삭제하여 본 incident 와 무관한 가설이 원인 진술에 섞이지 않도록 정리.

추가 조사 내용:

• 코드 탐색: app/models/concerns/searchable/reindex_helper.rb 전체 (Redis 키 포맷 searchable:reindex_helper:tmp_index:#{index_name}, expires_in: nil, lifecycle 메서드 4종 확인), app/models/concerns/searchable.rb:1-120 (dual-write 분기 위치 재확인), docs/zero_downtime_reindexing_guide.md (운영 절차가 수동 콘솔 실행임을 확인).
• Grep 호출자 조사: tesla 레포 전역에서 prepare_zero_downtime_reindex / migrate_data_to_tmp_index / promote_tmp_index_to_alias 의 production 호출자 0건 (spec + docs 만 매치).
• Searchable 포함 모델 인벤토리: app/models/*.rb 의 include Searchable::* 매치 결과 60+ 모델 확인 (Pano, Capture, Record, Group, Facility, Annotation, Workspace, Team, User, Bim, Floorplan 등).
• Datadog 로그: searching-datadog-logs 로 9개 reindex 관련 키워드 OR 쿼리를 cupixworks-api, cupixworks-worker 양쪽 14일 윈도우 검색 → 모두 0건.