RCA: Api::V1::PanosController#create Latency (avg 1321ms, max 1878ms)

Overview#

What Happened#

2026-05-26 03:50~06:16 UTC 사이에 ap-southeast-2 리전의 cupixworks-api 서비스에서 PanosController#create 엔드포인트가 평균 1321ms, 최대 1878ms의 응답 지연을 보였다. 총 12건의 slow request가 발생했으며, 모든 요청은 HTTP 200을 반환했지만 SLA 기준(500ms)을 초과했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-05-26T03:50:58Z — 최초 slow request 감지 (capture 73247, team 16)
2. 2026-05-26T03:51:37Z — 동시 다발 burst: team 180 + team 149 동시 upload
3. 2026-05-26T05:19:00Z — 두 번째 burst: capture 73275 (Lucy Walker, 5건 집중)
4. 2026-05-26T06:16:00Z — 세 번째 burst: capture 73306 (Jonah Nelson)
5. 2026-05-26T06:43:00Z — 정상 응답 복구 (~215ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#create",
  "service": "cupixworks-api",
  "occurrences": 12,
  "avg_ms": 1321,
  "max_ms": 1878,
  "sample_trace_id": "3611086426009172877"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 12
• 최초 발생: 2026-05-26T03:50:58.625Z
• 최근 발생: 2026-05-26T06:16:00.217Z

Root Cause Summary#

PanosController#create의 지연은 동시 bulk upload 시 발생하는 데이터베이스 contention이 주원인이다. 로그에서 확인된 가장 느린 요청(1854ms)의 DB 시간이 1018ms(전체의 55%)를 차지했으며, 정상 요청(215ms)의 DB 시간은 92ms에 불과했다. cupix-agent가 동일 capture에 대해 수십수백 개의 pano를 동시에 생성할 때, after_create 콜백에서 실행되는 ResourceFactory.create! (1-2건의 추가 INSERT) + counter_culture 카운터 UPDATE + Elasticsearch 인덱싱이 동일 DB 연결 풀에서 경합하면서 대기 시간이 누적된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/panos_controller.rb:43
• Factory creation: app/factories/pano_factory.rb:7
• DB save + callbacks: app/factories/base_factory.rb:124
• Resource creation (after_create): app/models/concerns/resourcable/pano.rb:73
• Elasticsearch indexing (after_commit): app/models/concerns/searchable.rb:34

1. Controller entry:

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

2. Factory - Capture lookup + permission checks (DB queries):

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

3. Model save triggers after_create callback - Resource creation with blocking retry:

def create_pano_resource
  self.pano_resource_count.times.each do
    attempt = 0
    max_attempt = 3

    begin
      if pano_type == 'panono'
        ResourceFactory.new(current_user: self.user).create!({ resourcable: self, name: self.name, kind: 'panono_origin' })
      end

      ResourceFactory.new(current_user: self.user).create!({ resourcable: self, name: self.name, revision: default_initial_revision })
    rescue => e
      Airbrake.notify({
        message: "Can't create pano resource [#{attempt}/#{max_attempt}]",
        resourcable_id: self.id
      })

      if attempt < max_attempt
        sleep attempt**2  # 0s, 1s, 4s blocking sleep
        attempt += 1
      else
        raise Cupix::Errors::NotImplemented.new(code: 'ENT10004', reason: e.message)
      end
    end
  end
end

pano_resource_count가 2일 경우, 각 pano 생성 시 최대 4건의 Resource INSERT가 실행된다. retry 시 sleep attempt**2로 인해 최대 4초의 blocking sleep이 발생할 수 있다.

4. After commit - Elasticsearch 동기 인덱싱:

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))
  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.index(base_request.merge(index: tmp_index))
  end
rescue StandardError => e
  Cupix::Logger.error("Index error - #{e.message}", class: self.class.name, function: __method__)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

Elasticsearch 인덱싱이 after_commit 콜백에서 동기적으로 실행된다. 정상 시에는 빠르지만, ES 클러스터 부하 또는 네트워크 지연 시 응답 시간에 직접 영향을 준다.

5. Counter culture update (after_commit):

Pano 모델의 counter_culture :capture (panos_count UPDATE)가 after_commit에서 실행되어 추가 DB write가 발생한다.

Log Evidence#

Datadog에서 사용한 쿼리:

service:cupixworks-api resource_name:"Api::V1::PanosController#create" @duration:>1000 env:production

가장 느린 요청 (1854ms total, 1018ms DB time):

{
  "timestamp": "2026-05-26T05:19:00.300Z",
  "duration_ms": 1854.78,
  "db_runtime_ms": 1018.34,
  "view_runtime_ms": 0.05,
  "host": "ip-10-1-145-251.ap-southeast-2.compute.internal",
  "user": "Lucy Walker (aialdp001, team 134)",
  "capture_id": 73275,
  "status": 200
}

정상 요청 비교 (06:43 UTC):

{
  "timestamp": "2026-05-26T06:43:xx.xxxZ",
  "duration_ms": 215,
  "db_runtime_ms": 92,
  "host": "ip-10-1-145-251.ap-southeast-2.compute.internal",
  "status": 200
}

Slow request의 DB 시간 분포 (ms):

1018, 778, 793, 650, 682, 308, 587, 585, 128, 611, 431

대부분의 요청에서 DB 시간이 전체 응답 시간의 50-60%를 차지하며, burst upload 시점에 집중적으로 발생했다. View/serialization 시간은 모두 0.05-0.16ms로 무시할 수 있는 수준이다.

Trace ID 3611086426009172877 로그 분석에서 확인된 동시 작업:

- Multiple Pano meta updates (world_transformation, set_parameters)
- EventService.publish_event (failed_record_count: 0/1)
- Facility cache resets (ID: 516) - repeated
- SQS message to pano-postprocessor queue
- Job state transitions: running -> stopping -> stopped

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

이 이슈는 애플리케이션 에러가 아닌 성능 지연이며, 모든 요청이 성공(HTTP 200)했다. 즉각적인 hotfix보다는 bulk upload 패턴에 대한 최적화가 필요하다.

• app/models/concerns/resourcable/pano.rb:73 — create_pano_resource에서 pano_resource_count > 1일 때 Resource를 batch INSERT로 변경하여 DB round-trip 감소
• app/models/concerns/searchable.rb:34 — _index_document를 비동기(BulkIndexWorker)로 전환하여 after_commit에서 ES 호출 제거

단기 개선 (1주 이내)#

• cupix-agent의 동시 요청 수를 제한하는 rate limiting 또는 request throttling 도입. 동일 capture에 대해 순차 처리 또는 batch API 제공
• counter_culture의 execute_after_commit: true를 유지하되, bulk update 시 deferred counter increment 패턴 적용
• DB connection pool 크기를 ap-southeast-2 인스턴스에 대해 점검하고 burst load에 맞게 조정

장기 개선 (재발 방지)#

• Bulk pano creation 전용 API 엔드포인트 도입 (bulk_create action) — 단일 트랜잭션에서 여러 pano + resource를 한 번에 생성
• after_create 콜백의 Resource 생성 로직을 background job으로 분리하여 request 응답 시간에서 제외
• APM에서 p95/p99 latency SLO 설정 및 자동 알림 구성

Monitoring#

• Datadog APM에서 PanosController#create p95 latency alert 추가:

avg(last_5m):p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::panoscontroller_create,env:production} > 1000

• DB time 비율 모니터링:

service:cupixworks-api resource_name:"Api::V1::PanosController#create" @db_runtime:>500

• 리전별 latency 비교 대시보드 구성 (ap-southeast-2 vs us-east-1 vs eu-west-1)

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard

모든 요청이 성공했으며 데이터 손실이 없다. 사용자 경험(upload 속도)에만 영향을 미치는 성능 이슈로, 기능적 결함은 아니다. 다만, burst load 증가 시 timeout 발생 가능성이 있어 중기적으로 최적화가 필요하다.