RCA: Api::V1::CapturesController#invoke latency (12.34s)

Overview#

What Happened#

2026-07-01 08:40 KST에 cupixworks-api 서비스의 POST /api/v1/captures/:id/invoke 요청 한 건이 12.34초 동안 지속되었다. 요청 자체는 HTTP 200으로 성공했지만, Invokable::CapturesController#invoke 액션이 동기적으로 무거운 재처리(reset/reprocess) 경로를 실행하면서 latency APM cluster 로 감지되었다. resolution_state 가 error 였던 Capture 722662를 error → processing 으로 되돌리는 재실행이었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 08:40:25 KST — POST /api/v1/captures/722662/invoke 요청 시작 (cluster first_seen, APM span 기록 시점).
2. 2026-07-01 08:41:44 KST — 응답 반환 (HTTP 200). Access log 기록. 클러스터의 12.34s span 을 포함한 request-lifetime.
3. 2026-07-01 08:42:02 KST — 클라이언트가 이어서 PUT /api/v1/captures/722662 (update) 실행.
4. 2026-07-01 08:43:30 KST — PUT /api/v1/captures/722662/check_zip_uploading (200) — zip 업로드 확인 성공.
5. 2026-07-01 08:44:17 KST — reconstruction_state has transitioned from error to processing on Capture 722662 — 재처리 상태 진입 확인.
6. 2026-07-01 08:45:38 KST — Zip lambda status_code(202) on Capture 722662 — zip lambda 호출 수락.
7. 2026-07-01 08:45:43 KST — Reconstruction job is created for capture 722662. job_id: 1164884 (CaptureInvoker#create_3d_reconstruction) — 실제 재구성 job 큐잉.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#invoke",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 12340,
  "max_ms": 12340,
  "sample_trace_id": "8502887697686579514"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-01 08:40 KST
• 최근 발생: 2026-07-01 08:40 KST
• 관련 인시던트: 2026-06-30-svc-cupixworks-api--unknown-1 (resolved 2026-07-01 08:58 KST). 본 클러스터는 이 서비스 인시던트의 8개 클러스터 중 하나로 자동 분류됨.

Root Cause Summary#

Api::V1::CapturesController#invoke 액션은 command 파라미터에 따라 여러 무거운 재실행 경로(reset_capture, create_3d_reconstruction, branch_capture, fix_tiles)를 모두 controller thread 안에서 동기 실행한다. 특히 CaptureInvoker#reset_capture 는 (1) 진행 중 job 순회 및 각 AwsTask#stop! 호출로 ecs_client.stop_task 를 sync 로 반복 실행하고, (2) panos.update_all(cluster_id: nil, meta: nil) 로 대량 update 를 수행하며, (3) BulkIndexWorker.perform_async 로 Elasticsearch 재색인을 트리거한다. Capture 722662 는 reconstruction_state 가 error 상태였고 (log evidence: 8:44:17 에 error → processing 전이 확인), reset/reprocess 계열 command 를 태우면서 위 external API 순회가 request lifetime 안에서 진행되어 12.34s latency 로 관측되었다. 즉, 이 latency 는 버그가 아니라 아키텍처적 특성 — controller 안에서 external service (ECS, DB, Elasticsearch worker enqueue)를 sync 로 처리하는 데서 발생하는 정상적인 tail latency 이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/captures_controller.rb:7 — include Invokable::CapturesController
• Action: app/controllers/concerns/invokable/captures_controller.rb:7-31 — invoke 액션이 command 파라미터로 dispatch
• Failure/slow point (reset 경로): app/invokers/capture_invoker.rb:217-235 — 순회 sync 처리
• External API call: app/models/aws_task.rb:161-176 — ecs_client.stop_task 동기 호출

def invoke
  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 'reset_capture'
    job = capture_invoker.reset_capture(user: current_user, option: option)
  when 'create_capture', 'upload_tiles'
    render_api
    return
  when 'fix_tiles'
    repository_instance.fix_tiles
  when 'branch_capture'
    @model = capture_invoker.branch_capture(user: current_user, option: option)
  when 'create_3d_reconstruction'
    job = capture_invoker.create_3d_reconstruction(user: current_user, option: option)
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: "Invalid command: #{command}")
  end

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

reset_capture 는 request thread 안에서 다음을 순차 실행한다:

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 ECS stop_task, per task
  job.stopped_state
end

@model.clusters.cycle_state_created.each(&:trash!)
@model.sys['reset_at'] = DateTime.now
@model.sys['reset_by_id'] = self.current_user.id if self.current_user.present? && self.current_user.is_a?(::User)
@model.reset_processing_attrs
@model.panos.update_all(cluster_id: nil, meta: nil)   # 대량 update

case @model.capture_type.material
when 'pano'
  reset_pano_capture
when 'video'
  reset_video_capture
end

BulkIndexWorker.perform_async('Pano', @model.panos.pluck(:id), operation = 'update')

각 stop! 은 ECS Control Plane API 를 호출한다:

def stop!
  begin
    resp = self.ecs_client.stop_task({
      task: task_id,
      cluster: $AWS[:ecs][:cluster_name],
      reason: 'Task has been stopped by Tesla'
    })
  rescue Aws::ECS::Errors::ClientException => e
    Cupix::Logger.error("ClientException on task_id: #{task_id}, message: #{e.message}", class: self.class.name, function: __method__, task: { task_id: task_id })
  # ...
  end
end

create_3d_reconstruction 경로도 sync 로 무거운 사전 작업을 수행한다:

def create_3d_reconstruction(opts = {})
  @model.create_capture_3d_reconstruction_invokable?
  # ...
  @model.zip                                     # zip lambda 호출 (async 이지만 http round-trip 발생)
  job = CreateCapture3dReconstructionJob.create!(params)   # DB write + SQS send in job.invoke_function
  Cupix::Logger.info("Reconstruction job is created for capture #{self.model.id}. job_id: #{job.id}", ...)

기대 동작 vs 실제 동작

• 기대: POST /invoke 는 job enqueue 후 즉시 202/200 반환 (<1s).
• 실제: reset 경로는 jobs.processing 개수만큼 ECS stop_task 를 순차 호출 + panos.update_all + Elasticsearch enqueue 를 controller thread 안에서 처리해 tail latency 가 커진다. Capture 722662 는 video capture 이며 관련 SQS 메시지 로그(08:45:43) 에서 500+ pano 가 여러 cluster 에 걸쳐 있음이 확인되어, 이런 대형 capture 에서 12s 는 재현 가능한 tail latency 범위다.

Log Evidence#

Datadog 쿼리 (재현):

service:cupixworks-api "captures" "invoke"
Time: 2026-06-30T23:30:00Z .. 2026-07-01T00:15:00Z

service:cupixworks-api "722662"
Time: 2026-06-30T23:35:00Z .. 2026-07-01T00:00:00Z

정상 tail (204 = fast, empty body) vs 오늘 관측된 200 응답 (실제 재구성 작업):

2026-06-27 15:40:44  [204] POST /api/v1/captures/74873/invoke   (fast path)
2026-06-27 15:33:08  [204] POST /api/v1/captures/74872/invoke   (fast path)
2026-07-01 08:41:44  [200] POST /api/v1/captures/722662/invoke  (heavy path — this cluster)

문제 요청의 lifecycle 로그:

2026-07-01 08:41:44  [200] POST /api/v1/captures/722662/invoke (Api::V1::CapturesController#invoke)
2026-07-01 08:44:17  reconstruction_state has transitioned from error to processing on Capture 722662
2026-07-01 08:45:38  Zip lambda status_code(202) on Capture 722662             (class: Capture, function: run_zip)
2026-07-01 08:45:43  Reconstruction job is created for capture 722662. job_id: 1164884
                     (class: CaptureInvoker, function: create_3d_reconstruction)

관련 SQS 페이로드에서 대형 capture 임을 확인 (일부 발췌):

{
  "validation_data": {
    "capture_id": 722662,
    "clusters": [
      {"cluster_id": 1415328, "panos": []},
      {"cluster_id": 1416950, "panos": [/* 130+ panos */]},
      {"cluster_id": 1416951, "panos": [/* ~26 panos */]},
      {"cluster_id": 1416952, "panos": [/* ~12 panos */]}
    ]
  },
  "sqs_data": {
    "region": "us-west-2",
    "queue_url": "https://sqs.us-west-2.amazonaws.com/002596530511/cupix-tesla-ece-gpu",
    "message": {"job": {"id": 1164884}, "session": {"id": 11549889}, "launch_mode": "CUPIXWORKS"}
  }
}

Status board 결과 — 본 클러스터는 svc:cupixworks-api::unknown 인시던트 2026-06-30-svc-cupixworks-api--unknown-1 에 포함되어 있음 (동일 시간대 유사 latency/에러 클러스터 8건 그룹):

scope: svc:cupixworks-api::unknown
active: null (resolved 2026-07-01T02:02:16Z)
resolved incident: 2026-06-30-svc-cupixworks-api--unknown-1
  cluster_ids: [3ce7061c..., 8a18b22e..., 6633f842..., 3580e20c..., 0c05ab76...,
                663ba9b7-3fdf-42d3-8d2c-504b673e8523, ee5150d4..., d8fb6118...]

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 조치 불필요: 단일 발생 (occurrence_count: 1), HTTP 200 성공, 재구성 job 은 정상 큐잉되고 상태 전이도 정상. 이 latency 는 대형 capture 에 대한 heavy invoke command 의 예상 tail. 별도 코드 수정을 요구하지 않는다.
• 만약 이 endpoint 의 P95 가 지속적으로 5s 초과로 관측된다면 아래 단기 개선을 검토.

단기 개선 (1주 이내)#

• 비동기화: app/controllers/concerns/invokable/captures_controller.rb:7-31 의 reset_capture / create_3d_reconstruction 경로를 background job 으로 위임하고, controller 는 202 Accepted 를 즉시 반환하도록 변경. Job 안에서 CaptureInvoker 를 호출하고 결과는 polling 또는 event 로 클라이언트에 통보. 이렇게 하면 request timeout 위험과 사용자 대기 시간 둘 다 줄어든다.
• ECS stop_task 배치화: app/models/aws_task.rb:161-176 를 순회 호출 대신 배치 처리(예: 병렬 thread pool 또는 별도 워커 job)로 변경.
• 관측성: CaptureInvoker 의 각 sub-step (unpublish!, stop_task 반복, update_all, BulkIndexWorker.perform_async) 에 timing log 추가. 어느 단계가 tail latency 를 차지하는지 정량화한다.

장기 개선 (재발 방지)#

• API design: heavy work 을 요구하는 endpoint 는 관례적으로 202 + polling/event 패턴을 사용하도록 팀 컨벤션화. 신규 controller action 에 대해 “controller 안에서 external API 를 sync 로 호출하지 말라” 는 review 룰 강화.
• APM SLO: Api::V1::CapturesController#invoke 의 P95 SLO 를 정의하고 (예: <3s), 위반 시 Datadog alert. 현재는 12s 도 조용히 통과됨.

Monitoring#

writing-datadog-monitoring-queries 지침에 따라 dashboard timeseries widget 에 사용 가능한 형태로 작성.

Invoke endpoint tail latency (P95):

p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::capturescontroller#invoke}

Invoke endpoint throughput:

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

Invoke endpoint error rate:

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::capturescontroller#invoke}.as_rate()

ECS stop_task 호출 빈도(간접 지표, log-based metric 이 필요할 수 있음):

logs("service:cupixworks-api @class:AwsTask @function:stop!").rollup("count").by("status")

Risk Assessment#

• Risk level: low — 단일 요청, 정상 응답, 후속 처리도 성공. 사용자 경험 손상은 12s 대기가 유일.
• 예상 복잡도: trivial (즉시 조치 시). 단기 개선(비동기화)은 standard 복잡도.