RCA: Api::V1::CapturesController#invoke Latency (1106ms)

Overview#

What Happened#

2026-05-27 05:23:58 UTC에 cupixworks-api 서비스의 Api::V1::CapturesController#invoke 엔드포인트에서 1106ms의 응답 시간이 관측되었다. 요청은 정상적으로 HTTP 200으로 완료되었으나, 500ms 임계값을 초과하는 latency로 클러스터가 생성되었다. Retool을 통한 배치 호출(동일 사용자가 42초 내 4건 호출) 중 발생하였다.

Quick Facts#

Timeline#

1. 05:23:40Z — 첫 번째 invoke 요청 (capture 702937, 674ms)
2. 05:23:58Z — 클러스터 대상 invoke 요청 (capture 702874, 1106ms)
3. 05:24:12Z — 세 번째 invoke 요청 (capture 702936, 1324ms)
4. 05:24:22Z — 네 번째 invoke 요청 (capture 702528, 925ms)

Error Log#

Datadog Logs

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

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (단, 동일 시간대 유사 latency 4건 존재)
• 최초 발생: 2026-05-27T05:23:58.210Z
• 최근 발생: 2026-05-27T05:23:58.210Z

Root Cause Summary#

create_3d_reconstruction 커맨드 실행 시, HTTP 요청 사이클 내에서 두 차례의 동기식 AWS Lambda 호출(Zip Lambda + Reconstruction Validator Lambda)과 대량 DB eager_load 쿼리(수백 개의 pano를 포함하는 클러스터 조회)가 순차적으로 실행되면서 누적 latency가 1106ms에 도달하였다. 이는 설계상 의도된 동작이나, 대용량 캡처에서는 500ms 임계값을 초과하게 된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/invokable/captures_controller.rb:7
• Invoker dispatch: app/invokers/capture_invoker.rb:48 — create_3d_reconstruction 메서드
• Zip Lambda 호출: app/models/concerns/zippable/capture.rb:5-10 → state transition → run_zip
• Job 생성 + Validator Lambda 호출: app/jobs/create_capture_3d_reconstruction_job.rb:37-93

Step 1: Controller → Invoker 진입

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 'create_3d_reconstruction'
    job = capture_invoker.create_3d_reconstruction(user: current_user, option: option)
  end

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

Step 2: Zip Lambda 동기 호출 (~300-400ms)

create_3d_reconstruction은 먼저 @model.zip을 호출하여 캡처의 pano 데이터가 변경되었는지 확인하고, 변경이 있으면 Zip Lambda를 동기적으로 호출한다.

def create_3d_reconstruction(opts = {})
  @model.create_capture_3d_reconstruction_invokable?

  # ... params setup ...

  @model.zip  # ← 동기식 Lambda 호출 트리거

  job = CreateCapture3dReconstructionJob.create!(params)
  # ...
end

def zip
  return unless source_changed?       # DB 쿼리: pano updated_at 비교
  return if self.zip_state_zipping?

  self.ready_zip_state                 # state transition → after_transition에서 run_zip 호출
end

State transition callback이 run_zip을 실행:

def run_zip
  _session = self.user.agent_team_session(self.team)
  payloads = zip_payload_data

  payloads.each do |payload|
    response = client.invoke({
      function_name: zip_service_name,
      invocation_type: 'Event',      # 비동기 호출이지만 invoke() 자체는 HTTP 응답 대기
      payload: payload.to_json
    })
    Cupix::Logger.info("Zip lambda status_code(#{response.try(:status_code)})...")
  end
end

로그에서 2건의 Zip Lambda 호출(202 반환)이 확인되었다. invocation_type: 'Event'이지만 AWS SDK의 invoke() 메서드는 Lambda 서비스의 HTTP 응답(202 Accepted)을 기다린다.

Step 3: Job 생성 + Reconstruction Validator Lambda (~400-500ms)

CreateCapture3dReconstructionJob.create!는 after_commit :run을 통해 execute → invoke_function을 동기적으로 실행한다.

def invoke_function
  capture = ::Capture.eager_load(clusters: :panos).where(id: self.jobable_id).last
  session = self.user.agent_team_session(self.jobable.team)

  reconstruction_payload_data = {
    validation_data: {
      capture_id: capture.id,
      clusters: capture.clusters.map do |cluster|
        {
          cluster_id: cluster.id,
          panos: cluster.panos.map { |pano| { pano_id: pano.id, video_frame_index: ... } }
        }
      end
    },
    # ...
  }

  response = client.invoke({
    function_name: reconstruction_service_name,
    invocation_type: 'Event',
    payload: _payload.to_json
  })
end

eager_load(clusters: :panos)는 해당 캡처의 모든 클러스터와 pano를 JOIN 쿼리로 로드한다. Datadog 로그에서 확인된 바, capture 702874는 10개 클러스터에 250+ pano를 포함하고 있어 이 쿼리만으로도 상당한 시간이 소요된다.

Step 4: DB 쿼리 누적 (~216ms)

로그에서 확인된 db: 215.96ms는 다음 쿼리들의 합산:

• source_changed?의 pano updated_at 조회
• zip_payload_data의 pano count 조회
• eager_load(clusters: :panos) JOIN 쿼리
• Job record INSERT
• Capture state 업데이트

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api @http.url_details.path:*captures*invoke* env:production

해당 요청의 로그 (request_id: 0a5ab5ee-82bd-4c3f-abff-08ee015184c9):

{
  "controller": "Api::V1::CapturesController",
  "action": "invoke",
  "method": "POST",
  "status": 200,
  "duration": 1104.58,
  "db": 215.96,
  "view": 0.07,
  "user": "chan.lee@cupix.com",
  "user_agent": "Retool/2.0"
}

동일 request_id로 확인된 하위 작업 로그:

[05:23:59Z] Zippable#source_changed? — Current pano's updated time:1779855898 and Previous pano's update time:1779851000
[05:23:59Z] Zippable#run_zip — Zip lambda status_code(202) on Capture 702874 (x2)
[05:23:59Z] EntityUpdates::Child#reset_parent_cached_entity_updates — Facility 16394
[05:24:00Z] CaptureInvoker#create_3d_reconstruction — job_id: 1088352, capture: 702874
[05:24:00Z] CreateCapture3dReconstructionJob#invoke_function — Sending message to 3d-reconstruction-queue (250+ panos, 10 clusters)
[05:24:00Z] CreateCapture3dReconstructionJob#execute — status_code(202)
[05:24:00Z] Capture#log_event — create_3d_reconstruction

동일 시간대 다른 invoke 요청도 유사 패턴:

05:23:40Z — capture 702937: 674ms (db: 180ms)
05:24:12Z — capture 702936: 1324ms (db: 195ms)
05:24:22Z — capture 702528: 925ms (db: 217ms)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

현재 latency는 설계상 의도된 동작의 결과이며, 에러나 장애가 아닌 정상 완료 요청이다. 단일 발생(1건)이고 사용자 영향도 없으므로 즉시 조치는 불필요하다.

만약 500ms 임계값 위반을 해소하려면:

• app/invokers/capture_invoker.rb:69 — @model.zip 호출을 비동기 worker로 이동
• app/jobs/create_capture_3d_reconstruction_job.rb:37 — after_commit :run에서 run을 Sidekiq worker로 위임하여 Lambda 호출을 HTTP 요청 사이클 밖으로 분리

단기 개선 (1주 이내)#

• Zip Lambda 호출을 perform_async로 비동기화하여 invoke 응답에서 제거
• CreateCapture3dReconstructionJob#invoke_function의 eager_load 쿼리를 job run 시점(비동기)으로 완전 분리
• 현재 run_on_create?가 true를 반환하여 after_commit에서 동기 실행되는데, 이를 false로 변경하고 별도 worker에서 execute 호출

장기 개선 (재발 방지)#

• Invoke 패턴 전반에 대해 "HTTP 요청 내 동기 외부 호출 금지" 원칙 적용
• Lambda 호출은 모두 Sidekiq worker를 통해 비동기 실행하도록 아키텍처 변경
• 대용량 캡처에 대한 별도 처리 경로(batch invoke) 도입 검토

Monitoring#

• APM latency P95/P99 모니터링:

service:cupixworks-api resource_name:"Api::V1::CapturesController#invoke" env:production @duration:>500ms

• Zip Lambda 호출 빈도 및 duration 추적:

service:cupixworks-api "Zip lambda status_code" @class:Zippable

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 근거: 에러 없이 정상 완료된 요청이며, 단일 발생이다. 동일 패턴이 모든 create_3d_reconstruction invoke에서 반복되지만 사용자 경험에 직접적 영향을 주는 장애는 아니다. 비동기화 변경은 기존 callback 구조 수정이 필요하여 standard 복잡도로 평가한다.