RCA: CapturesController#check_process_output_uploading Latency Spike (3334ms)

Overview#

What Happened#

2026-05-26 03:46 UTC에 cupixworks-api의 Api::V1::CapturesController#check_process_output_uploading 엔드포인트가 3334ms의 응답 시간을 기록했다. 이 중 2682ms(80.5%)가 DB 시간이었으며, capture 702484의 process output 확인 과정에서 postprocessor job 완료 콜백이 동기적으로 inline 실행되면서 다수의 state machine 전환과 after_update 콜백 체인이 발생했다.

Quick Facts#

Affected Teams#

Timeline#

1. 03:46:06Z — process_output_upload_url 호출 (155ms, 정상)
2. 03:46:12Z — check_process_output_uploading 호출 시작, capture 702484
3. 03:46:12Z — S3 HEAD 요청 후 state='uploaded' 설정, @model.save 호출
4. 03:46:12Z — Postprocessor _finish → job.stopping_state! → inline 콜백 cascade 시작
5. 03:46:15Z — 14회 facility cache reset, state transitions (done→finalizing→done), 응답 완료 (3334ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#check_process_output_uploading",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 3334,
  "max_ms": 3334,
  "sample_trace_id": "4243407490746249828"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-05-26T03:46:07.933Z
• 최근 발생: 2026-05-26T03:46:07.933Z

전체 100건의 check_process_output_uploading 요청 중 중앙값은 278ms, 평균 413ms이며 이 건만 3334ms로 극단적 outlier이다. p95는 773ms. 사용자 영향은 cupix-agent의 polling 대기 시간 증가로 제한적이나, 동일 패턴이 반복될 경우 처리 완료 지연으로 이어질 수 있다.

Root Cause Summary#

Capture 702484의 check_process_output_uploading 요청이 S3 존재 확인 후 @model.save를 호출하는 시점에, postprocessor job의 완료 콜백이 JobCallbackWorker.perform_inline으로 동기 실행되었다. 이로 인해 단일 HTTP 요청 내에서 job stopping → job stopped → capture finalizing → capture done의 state machine 전환 체인이 발생했고, 각 전환마다 after_update 콜백(EntityUpdates cache reset, Eventable event publish, ParentUpdatable)이 반복 실행되어 총 2682ms의 DB 시간이 소모되었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/process_outputable_controller.rb:9
• Repository: app/repositories/concerns/process_outputable_repository.rb:10-20
• Model method: app/models/concerns/process_outputable/capture.rb:49-59
• Failure point (latency): app/repositories/concerns/process_outputable_repository.rb:14 (@model.save)

1단계: Controller → Repository

def check_process_output_uploading
  case @model.process_output_state
  when 'uploading'
    @model.check_process_output_uploading
    @model.save                              # <-- 2682ms DB time의 원인
  else
    raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: "Invalid state: #{@model.process_output_state}")
  end
  @model
end

2단계: Model에서 S3 확인 후 state 변경

def check_process_output_uploading
  _object = process_output_object(ver: process_output_revision + 1)
  if _object.exists?                          # S3 HEAD 요청 (통상 50-200ms)
    increase_process_output_revision
    change_process_output_state('uploaded')    # sys JSON 컬럼 값 변경
    return true
  end
  change_process_output_state('missing')
end

기대 동작: @model.save가 단순히 sys JSON 컬럼 업데이트로 빠르게 완료(~20ms). 실제 동작: save 호출 시 after_update 콜백 체인이 시작되고, 동시에 postprocessor job 완료 콜백이 동기 실행되면서 cascade 발생.

3단계: Job 완료 콜백 (동기 inline 실행)

after_transition any => :stopping do |job, transition|
  JobCallbackWorker.perform_inline(job.id, 'job_stopping_callback')
end

perform_inline은 Sidekiq worker를 비동기 큐가 아닌 현재 스레드에서 직접 실행한다. 이로 인해 전체 job completion cascade가 HTTP 요청 내에서 동기 실행된다.

4단계: Capture state 전환 cascade

def job_stopped_callback(job)
  run_callbacks(:job_stopped_callback) do
    if job.update_jobable_state?
      update_refinement_state
      initiate_editing_state
      start_finalization
      update(processing_finished_at: DateTime.now)   # after_update 트리거
      stat_processing_finished_at
      self.log_trace_event('processing_finished')
      self.error_code = job.error_code if job.error_code.present?
      flush_record_geo_coordinate_in_worker if record_geo_coordinate_flush_required?
      done_state                                      # finalizing -> done 전환
    end
  end
end

5단계: 각 update마다 반복되는 after_update 콜백

included do
  after_create :reset_parent_cached_entity_updates
  after_update :reset_parent_cached_entity_updates
end

def reset_parent_cached_entity_updates
  self.class.parent_classes.each do |class_name|
    Cupix::Logger.info("reset #{class_name} (ID: #{self.send("#{class_name.underscore}_id")}) cached entity updates")
    Rails.cache.delete(entity_updates_cache_key(class_name, self.send("#{class_name.underscore}_id")))
  end
end

Capture 모델의 after_update가 7회 이상 발생하며(state transitions + 명시적 update 호출), 각각 facility cache reset과 Kinesis event publish를 트리거하여 14+ 회의 "reset Facility cached entity updates" 로그가 생성된다.

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api "check_process_output_uploading"
Time: 2026-05-26T02:46:00Z to 2026-05-26T04:46:00Z

service:cupixworks-api @action:check_process_output_uploading @duration:>1000
Time: 2026-05-26T02:46:00Z to 2026-05-26T04:46:00Z

최악 요청 로그 (capture 702484):

{
  "timestamp": "2026-05-26T03:46:12.078Z",
  "request_id": "cacc8a9a-9f5b-4afd-9fef-6235413c547f",
  "method": "PUT",
  "path": "/api/v1/captures/702484/check_process_output_uploading",
  "status": 200,
  "duration_ms": 3332.25,
  "db_ms": 2682.94,
  "view_ms": 0.08,
  "host": "ip-10-1-19-190.us-west-2.compute.internal",
  "user": "cloudeys@howbuild.com",
  "team": "smacon",
  "team_id": 1061
}

Trace 내 관찰된 콜백 체인:

- Capture state: done -> finalizing -> done
- Job 1086455 state: stopped -> stopping -> stopped
- job_stopping_callback fired
- job_stopped_callback fired
- reset Facility (ID: 15395) cached entity updates (x14)
- Published event (multiple)
- processing_finished event
- run_3d_reconstruction? validation
- capture publish skipped

정상 요청과의 비교:

정상 (p50): duration=278ms, db=28ms
이상치:     duration=3334ms, db=2682ms (96x DB time)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/statable/job.rb:95-98 — JobCallbackWorker.perform_inline을 JobCallbackWorker.perform_async로 변경하여 job completion cascade를 HTTP 요청 외부에서 비동기 실행
• 이렇게 하면 check_process_output_uploading은 S3 확인 + sys 컬럼 update만 수행하고 즉시 응답하며, 무거운 state machine 전환은 Sidekiq worker에서 처리

단기 개선 (1주 이내)#

• app/models/concerns/jobable/capture.rb:29-48의 job_stopped_callback 내 다수의 개별 update 호출을 하나의 트랜잭션으로 통합하여 after_update 콜백 발동 횟수를 최소화
• app/models/concerns/entity_updates/child.rb의 reset_parent_cached_entity_updates에서 동일 요청 내 중복 cache reset을 deduplication (예: RequestStore 활용)

장기 개선 (재발 방지)#

• Job completion pipeline을 event-driven 아키텍처로 전환하여 state machine 전환을 각각 독립된 Sidekiq job으로 분리
• Capture 모델의 after_update 콜백 수를 감사하고, 불필요한 반복 실행을 방지하는 callback batching 메커니즘 도입
• APM에서 check_process_output_uploading 엔드포인트의 p95 latency에 대한 알림 설정으로 regression 조기 감지

Monitoring#

• check_process_output_uploading p95 duration 임계치 알림 (1000ms 초과 시)
• Job callback inline 실행 시간 추적을 위한 custom metric 추가

service:cupixworks-api resource_name:"Api::V1::CapturesController#check_process_output_uploading" @duration:>1000

service:cupixworks-api "JobCallbackWorker" "perform_inline" @duration:>500

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — perform_inline → perform_async 변경은 단순하나 job completion 순서 보장 및 응답 시 state 반영 여부에 대한 integration 검증 필요