RCA: Slow Api::V1::CapturesController#reinvoke on eu-central-1 (avg 11.7s)

Overview#

What Happened#

2026-06-25 02:59 KST (17:59 UTC) eu-central-1 region에서 POST /api/v1/captures/40130/reinvoke 요청 한 건이 11,695 ms 동안 처리되며 latency 클러스터로 검출됐다. 해당 요청은 command=reprocess_capture로 들어와 controller 내부에서 동기적으로 CaptureInvoker#reprocess_capture → CaptureInvoker#reset_capture 전체 플로우(unpublish, processing job 중단, AWS task stop, panos 일괄 update, refinement/3D reconstruction 재설정, BulkIndex enqueue, Slack post 2회)를 실행했다. status는 200으로 정상 완료됐고 같은 시간대에 5xx 에러나 외부 의존성 장애는 관측되지 않았다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-25 02:59:31 KST — POST /api/v1/captures/40130/reinvoke 요청 시작 (cluster last_seen = 2026-06-24T17:59:31.677Z UTC).
2. 2026-06-25 02:59:43 KST — reset_capture 내부 단계가 거의 동시에 emit됨: "Capture 40130 reset refinement job" / "...reset refinement job done" / "Capture 40130 reset 3d_reconstruction"(2회) / "Capture job is created for capture 40130. job_id: 113483" / "preprocessor agent is invoked for capture 40130" / "invoke capture processing for capture 40130." (Datadog logs).
3. 2026-06-25 02:59:43 KST — refinement_state refined → draft 전이 로그.
4. 2026-06-25 02:59:44 KST — 응답 200 완료. 총 소요 11,695 ms (cluster 통계).
5. 2026-06-25 03:04:59 KST — 후속 처리 시작: "skatmaster is invoked for capture 40130. job id: 113483".

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#reinvoke",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11695,
  "max_ms": 11695,
  "sample_trace_id": "2389808484529763761"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-25 02:59 KST
• 최근 발생: 2026-06-25 02:59 KST
• Region: eu-central-1 (단일 region)

Root Cause Summary#

Api::V1::CapturesController#reinvoke는 controller 스레드 내부에서 CaptureInvoker#reprocess_capture를 동기 실행하며, 이 메서드는 다시 reset_capture 전체를 호출한다. reset_capture는 단일 트랜잭션처럼 보이지만 실제로는 (1) unpublish!, (2) @model.jobs.processing 반복 + 각 job의 aws_tasks.running.each(&:stop!) (외부 AWS API 호출), (3) @model.clusters.cycle_state_created.each(&:trash!), (4) @model.panos.update_all(...), (5) refinement / 3D reconstruction 재설정, (6) BulkIndexWorker.perform_async('Pano', ...), (7) Slack webhook POST 2회 — 등 누적 데이터 양에 비례하는 다수의 DB write와 외부 호출을 수행한다. Capture 40130은 oldest-id 군에 속하는 누적 capture로, 연관된 panos / jobs / aws_tasks / clusters 수가 크기 때문에 동기 reset 비용이 11.7 s까지 누적된 것이다. 외부 의존성 장애나 DB 락 증거는 없다 — 즉 코드 경로가 본질적으로 N에 비례해 무거운 구조라는 점이 root cause다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/invokable/captures_controller.rb:33
• Branch: command == 'reprocess_capture' → capture_invoker.reprocess_capture
• Heavy fan-out: app/invokers/capture_invoker.rb:272-291 (reprocess_capture) → app/invokers/capture_invoker.rb:207-255 (reset_capture)
• Failure point (latency, not error): reset_capture 본체 — 외부 호출 + N+1 패턴 + 동기 Slack POST

def reinvoke
  command = params[:command]
  option = parse_option_json(params[:option_json])
  capture_invoker = CaptureInvoker.new(model: @model, current_user: current_user, current_team: @current_team)

  case command
  when 'resume_capture'
    capture_invoker.resume_capture
  when 'reprocess_capture'
    capture_invoker.reprocess_capture(option: option)
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: "Invalid command: #{command}")
  end

  render_api Renderable.new({
    contents: @model
  })
end

def reprocess_capture(opts = {})
  raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied') unless Pundit.policy(self.current_user, @model).reinvoke?
  raise Cupix::Errors::Entity.new(code: 'ENT10000', reason: 'Model has invalid state to reprocess') unless @model.reprocessible?

  self.reset_capture(opts, force: true)

  post_slack("[Repositories::Capture] Begin to reprocess capture #{@model.id}")

  @model.sys['reprocessed_at'] = DateTime.now
  ...
  @model.ready_to_process_state!
  @model.save!

  post_slack("[Repositories::Capture] Finished to reprocess capture #{@model.id}")
  ...
end

def reset_capture(opts = {}, force: false)
  ...
  post_slack("[Repositories::Capture] Begin to reset capture #{@model.id}")

  @model.unpublish!

  @model.jobs.processing.each do |job|
    job.aws_tasks.running.each(&:stop!)   # ← 외부 AWS API 호출, N×M 반복
    job.stopped_state
  end

  @model.clusters.cycle_state_created.each(&:trash!)
  @model.sys['reset_at'] = DateTime.now
  ...
  @model.reset_processing_attrs
  @model.panos.update_all(cluster_id: nil, meta: nil)   # ← 단발 SQL이지만 panos 수에 비례

  case @model.capture_type.material
  when 'pano'
    reset_pano_capture
  when 'video'
    reset_video_capture                                  # ← cycle_state_created 추가 반복
  end

  BulkIndexWorker.perform_async('Pano', @model.panos.pluck(:id), operation = 'update')
  ...
  reset_refinement if @model.refiner_execution?
  reset_3d_reconstruction
  post_slack("[Repositories::Capture] Finished to reset capture #{@model.id}")
  ...
end

기대 동작: HTTP 핸들러는 빠르게 응답하고 무거운 reset/reprocess는 background job으로 분리되어야 한다.

실제 동작: controller 스레드가 (1) Slack POST 2회 + reprocess 단계에서 추가 2회 = 최대 4회의 외부 HTTPS 호출, (2) jobs.processing.each { aws_tasks.running.each(&:stop!) } 의 N×M 외부 AWS API 호출, (3) cycle_state_created.each(&:trash!) 반복, (4) panos.update_all, (5) BulkIndexWorker.perform_async enqueue, (6) refinement/3d reconstruction state 머신 전이까지 모두 동기 처리하면서 11.7 s 누적. Capture 40130 처럼 누적 데이터가 많은 capture에서 시간이 비례 증가한다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "CapturesController#reinvoke"
service:cupixworks-api "capture 40130" OR "Capture 40130"
service:cupixworks-api region:eu-central-1 status:error

reinvoke 진입과 reset 단계가 같은 초(02:59:43 KST)에 폭주하며 emit된 로그:

2026-06-25 02:59:44  [200] POST /api/v1/captures/40130/reinvoke (Api::V1::CapturesController#reinvoke)
2026-06-25 02:59:43  invoke capture processing for capture 40130.                 (Capture#invoke_capture)
2026-06-25 02:59:43  Capture 40130 reset 3d_reconstruction                        (reset_3d_reconstruction)
2026-06-25 02:59:43  Capture 40130 reset refinement job done                      (reset_refinement)
2026-06-25 02:59:43  Capture 40130 reset refinement job                           (reset_refinement)
2026-06-25 02:59:43  preprocessor agent is invoked for capture 40130. job id: 113483   (Capture#run_preprocessor_agent)
2026-06-25 02:59:43  Capture job is created for capture 40130. job_id: 113483    (CaptureInvoker#create_capture)
2026-06-25 02:59:43  Capture 40130 reset 3d_reconstruction                        (reset_3d_reconstruction)
2026-06-25 02:59:43  refinement_state has transitioned from refined to draft on Capture 40130

같은 시간대 eu-central-1 region에 5xx, 외부 의존성 timeout, DB 락 관련 로그는 발견되지 않았다(쿼리 service:cupixworks-api region:eu-central-1 status:error 24h 결과는 무관한 BIM360 token / set_upload_state 메시지 7건뿐). status-board는 같은 시간대에 svc:cupixworks-api::unknown scope의 resolved 인시던트(2026-06-24-svc-cupixworks-api--unknown-2)를 보고하지만, 해당 인시던트의 다른 cluster들과 root_cause 공통점은 "단순 latency"이며 dependency 장애는 없다.

같은 endpoint의 7일 latency 분포(@duration:>5000ms 쿼리)에서 30건 이상이 5 s를 넘긴다 — 이는 한 건짜리 outlier가 아니라 엔드포인트 자체의 구조적 latency tail임을 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 코드 변경 없음. 11.7 s는 사용자에게 길지만 200 OK로 처리되었고 데이터 정합성 문제는 없다. 단일 region 단일 건이므로 SLO 위반 알림이 없다면 즉시 hotfix는 불필요.
• 모니터링 강화만 즉시 적용 (아래 Monitoring 섹션).

단기 개선 (1주 이내)#

• reinvoke를 fire-and-forget 패턴으로 분리. app/controllers/concerns/invokable/captures_controller.rb:33-50에서 controller가 직접 reprocess_capture를 호출하지 말고, 권한/reprocessible? 검증 후 이미 존재하는 background job(CreateCaptureJob/별도 reprocess job)으로 enqueue하고 즉시 202 Accepted 응답. 응답 본문에는 @model의 진행 상태 또는 job id를 반환.
• Slack post를 동기 경로에서 제거. app/invokers/capture_invoker.rb:213, 251, 278, 287의 post_slack 4회는 latency tail에 직접 기여한다. Sidekiq worker나 ActiveJob으로 비동기화하거나, 최소한 Cupix::HttpClient.post에 짧은 timeout을 명시.
• @model.jobs.processing.each { |job| job.aws_tasks.running.each(&:stop!); ... } 루프를 일괄 처리화. aws_tasks.running 전체를 모아 한 번에 stop / 또는 background에서 stop. app/invokers/capture_invoker.rb:217-220.

장기 개선 (재발 방지)#

• reset_capture/reprocess_capture 자체를 background pipeline 으로 재설계. 컨트롤러는 "reprocess 요청을 큐에 등록"만 담당하고, 상태 머신 전이 / panos update / refinement 재설정 / 3d reconstruction 재설정은 idempotent한 worker 한 개에서 순차 실행. 누적 capture의 데이터 크기에 사용자 응답 시간이 의존하지 않게 한다.
• API 응답 SLO를 endpoint 단위로 수립 (예: Api::V1::CapturesController#reinvoke p95 < 1 s). 현재 cluster_type=latency 검출 임계가 있는 만큼 SLO와 매칭.

Monitoring#

추가/유지할 메트릭과 알림:

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

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::capturescontroller#reinvoke} by {region}

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

알림 권장: p95 > 5s for 5m (region별), 또는 단일 sample이 10 s 초과 시 노티.

Risk Assessment#

• Risk level: low (단일 건, 200 OK, 데이터 정합성 문제 없음, 외부 의존성 장애 아님)
• 예상 복잡도: standard (단기 개선은 controller→job 분리 리팩터링이라 영향 범위가 reinvoke 흐름 전반)