RCA: AnalyzePanoWorker Lock wait timeout on capture 737963

Overview#

What Happened#

2026-07-18 15:04 KST, cupixworks-worker(production, us-west-2)의 AnalyzePanoWorker::perform가 capture 737963에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded로 실패했다. 오류는 1회 발생했고 Sidekiq 자동 재시도(retry: 1)로 15:04:27 KST에 재시도가 성공하여 15:06:53 KST에 정상 완료됐다. 최종 사용자 영향은 없다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-18 15:02:35 KST — Capture 737963에서 run_3d_reconstruction? 검증 시작 (Capture#run_3d_reconstruction?)
2. 2026-07-18 15:02:49 KST — Reconstruction 잡 생성 (job_id 1208310), CaptureInvoker#create_3d_reconstruction
3. 2026-07-18 15:02:55 KST — AnalyzePanoWorker::perform | begins on 737963 (1차 실행)과 동시에 Capture 737963 processing is completed (Capture#notify_processing_completed), Capture intelligence job 생성 (job_id 1208311)
4. 2026-07-18 15:04:03 KST — AnalyzePanoWorker::perform가 Mysql2::Error::TimeoutError: Lock wait timeout exceeded로 실패 (begins로부터 68초 경과 → InnoDB innodb_lock_wait_timeout 대기 후 타임아웃 추정)
5. 2026-07-18 15:04:13 KST — reconstruction_state has transitioned from none to queued on Capture 737963
6. 2026-07-18 15:04:19 KST — update_associated_sitetracks, update_associated_deviations 실행
7. 2026-07-18 15:04:25 KST — Reconstruction/Capture Intelligence SQS 메시지 전송
8. 2026-07-18 15:04:27 KST — Sidekiq 재시도로 AnalyzePanoWorker::perform | begins on 737963 (2차 실행)
9. 2026-07-18 15:04:47 KST — AnalyzePano::analyze | capture_id=737963 total_panos=297
10. 2026-07-18 15:06:53 KST — AnalyzePanoWorker::perform | uploaded and waiting callback on 737963 (재시도 성공)

Error Log#

Datadog Logs

AnalyzePanoWorker::perform | error on 737963 - Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixworks-worker
• 발생 횟수: 1
• 최초 발생: 2026-07-18 15:04:03 KST
• 최근 발생: 2026-07-18 15:04:03 KST
• 사용자 영향: 없음 — Sidekiq 자동 재시도(1차)로 복구, capture 737963의 pano 분석은 15:06:53 KST에 정상 진입

Root Cause Summary#

AnalyzePanoWorker는 capture.processing_analysis_state! 호출로 captures row (id=737963)를 analysis_state=processing으로 갱신한다. 그러나 동일한 capture 로우에 대해 여러 후속 처리(publish 완료 콜백에 의해 트리거되는 reconstruction_state 전이, summary_state 전이, 관련 sitetracks/deviations 업데이트, capture intelligence 잡 생성 등)가 15:02:55 KST 전후에 동시에 진행 중이었다. InnoDB row-level lock 경합으로 processing_analysis_state!의 UPDATE captures ...가 대기하다 innodb_lock_wait_timeout(약 50초 이상)을 초과해 Mysql2::Error::TimeoutError가 발생했다. Sidekiq retry: 1 설정 덕에 24초 후 재시도가 곧바로 성공했다. 즉, 드문 row 잠금 경합에 의한 transient 오류이며 코드 결함이라기보다는 다중 상태 전이 파이프라인의 타이밍 상 발생 가능한 정상 케이스에 가깝다.

Technical Analysis#

Code Path#

• Entry point: app/workers/analyze_pano_worker.rb:5 (AnalyzePanoWorker#perform)
• Failure point: app/workers/analyze_pano_worker.rb:12 (capture.processing_analysis_state!) — state_machine gem이 생성한 bang 전이 메서드로, 내부적으로 UPDATE captures SET analysis_state='processing', analysis_state_updated_at=... WHERE id=?를 실행한다.

class AnalyzePanoWorker
  include Sidekiq::Worker
  sidekiq_options queue: :analyze_pano, retry: 1

  def perform(capture_id)
    capture = ::Capture.find(capture_id)
    Cupix::Logger.info("AnalyzePanoWorker::perform | begins on #{capture_id}", class: self.class.name, function: __method__)

    return unless capture.analyzable?

    begin
      capture.processing_analysis_state!
      Cupix::Compass::SceneUnderstanding::AnalyzePano.analyze(capture)
      AnalysisTimeoutWorker.perform_in(3.hours, capture_id)

      Cupix::Logger.info("AnalyzePanoWorker::perform | uploaded and waiting callback on #{capture_id}", class: self.class.name, function: __method__)
    rescue => e
      capture.error_analysis_state!
      Cupix::Logger.error("AnalyzePanoWorker::perform | error on #{capture_id} - #{e.message}", class: self.class.name, function: __method__)
      raise e
    end
  end
end

capture.analyzable?는 analysis_state가 created 또는 error일 때만 실행을 허용한다:

def analyzable?
  %w[created error].include?(analysis_state)
end

동일한 capture에 대해 병렬로 진행되는 다른 상태 전이 예시 — reconstruction_state도 captures row에 UPDATE를 발생시킨다:

before_transition from: any, to: any do |model, transition|
  model.reconstruction_state_updated_at = DateTime.now
end
# ...
after_transition from: any, to: any do |model, transition|
  Cupix::Logger.info("reconstruction_state has transitioned from #{transition.from} to #{transition.to} on Capture #{model.id}",
                     ...)
end

기대 동작: publish 완료 시점에 여러 상태 전이(reconstruction_state, summary_state, analysis_state)와 관련 잡 생성(create_3d_reconstruction, create_capture_intelligence)이 병렬로 트리거되어도 각각의 짧은 트랜잭션이 순차적으로 성공한다.

실제 동작: 15:02:55 KST에 트리거된 AnalyzePanoWorker가 processing_analysis_state!를 호출한 시점에, 같은 captures.id=737963 row를 잠그고 있는 다른 트랜잭션(reconstruction 준비 로직 등)이 오래 유지되어 analyze_pano 워커의 UPDATE가 innodb_lock_wait_timeout을 초과하고 68초 후 실패했다. 이후 재시도는 경합이 해소된 후에 실행되어 정상 완료.

Log Evidence#

Datadog query (재현):

service:cupixworks-worker (737963) @environment:production

Time window: now-6h (2026-07-18 KST 오전~오후).

핵심 이벤트 순서(발췌, KST):

2026-07-18 15:02:35  info  start validation for 3D reconstruction. capture_id: 737963, editing_support: true
2026-07-18 15:02:37  info  3D Reconstruction has invoked on publish. capture_id: 737963
2026-07-18 15:02:45  info  Zip lambda status_code(202) on Capture 737963           (x2)
2026-07-18 15:02:49  info  Reconstruction job is created for capture 737963. job_id: 1208310
2026-07-18 15:02:55  info  Analysis has been triggered. capture_id: 737963
2026-07-18 15:02:55  info  AnalyzePanoWorker::perform | begins on 737963            (attempt 1)
2026-07-18 15:02:55  info  Capture 737963 processing is completed. record_id:138414
2026-07-18 15:02:55  info  Capture intelligence job is created for capture 737963. job_id: 1208311
2026-07-18 15:02:55  info  'create_capture_intelligence' job(1208311) run for capture 737963
2026-07-18 15:04:03  error AnalyzePanoWorker::perform | error on 737963 - Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction
2026-07-18 15:04:13  info  reconstruction_state has transitioned from none to queued on Capture 737963
2026-07-18 15:04:19  info  Updating associated deviations for Capture 737963
2026-07-18 15:04:19  info  Updating associated sitetracks for Capture 737963
2026-07-18 15:04:25  info  Sending message to 3d-reconstruction-queue: {...capture_id=>737963...}
2026-07-18 15:04:25  info  Sending message to https://sqs.us-west-2.amazonaws.com/.../cupix-capture-intelligence-agent-production.fifo
2026-07-18 15:04:27  info  AnalyzePanoWorker::perform | begins on 737963            (attempt 2, retry)
2026-07-18 15:04:27  info  summary_state transitioned from none to queued on Capture 737963
2026-07-18 15:04:47  info  AnalyzePano::analyze | capture_id=737963 total_panos=297
2026-07-18 15:06:53  info  AnalyzePanoWorker::perform | uploaded and waiting callback on 737963

주요 관찰:

• 1차 begins (15:02:55)와 에러(15:04:03) 사이 간격은 68초로, InnoDB 기본 innodb_lock_wait_timeout (50초) 이상. 데이터베이스 락 대기 후 타임아웃 시나리오와 일치.
• 재시도(15:04:27)는 실패 후 24초 내로 즉시 성공했다 — 경합이 잠깐이었음을 의미한다.
• 같은 시간대에 다른 cupixworks-worker 에러(batch_pull! ECS IAM, flush_geo_coordinate S3 me-south-1 TCP timeout)가 다수 있으나 서로 다른 원인/시스템으로, capture 737963 락 타임아웃과 무관하다 (Datadog service:cupixworks-worker status:error @environment:production 5:00~6:15 UTC 범위에서 확인).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 1회 발생, 재시도로 자동 복구되었고 사용자 영향 없음. Sidekiq retry: 1이 의도대로 작동했다.

단기 개선 (1주 이내)#

• 로그 레벨 재검토 — 이 오류는 재시도로 자동 복구되며 root cause가 정상 파이프라인 상의 transient 락 경합이다. 최종 실패(재시도 소진)만 error로 남기고 1차 실패는 warn으로 강등하는 방안 검토. 대상 파일: app/workers/analyze_pano_worker.rb:19. Sidekiq의 sidekiq_retries_exhausted 훅에서만 error 로그를 남기고, in-progress rescue에서는 warn으로 처리하면 오탐 알람 감소.
• 알람 임계값 조정 — 같은 fingerprint의 오류가 15분 내 여러 capture에 걸쳐 다수 발생할 때만 알람이 뜨도록 튜닝. 단일 이벤트는 배포 후 재시도가 성공하면 자동 무시.
• 회귀 확인 — Datadog service:cupixworks-worker "AnalyzePanoWorker" "Lock wait timeout" 쿼리로 최근 14일 발생 빈도 확인. 만약 빈도가 하루 여러 건 이상이면 H1의 락 경합이 상시화된 것이므로 아래 장기 개선을 우선 추진.

장기 개선 (재발 방지)#

• 상태 전이 파이프라인 분리 — 하나의 publish 이벤트에서 파생되는 analysis_state, reconstruction_state, summary_state 전이 및 update_associated_deviations, update_associated_sitetracks 업데이트를 순차 실행하도록 큐(예: 단일 capture-lifecycle Sidekiq 큐, sidekiq_options lock: :until_executed)로 직렬화. 관련 코드: app/models/concerns/reconstruction.rb, app/models/concerns/analyzable.rb, app/models/concerns/statable/capture.rb:465-488.
• 작은 상태 전이 트랜잭션 — 상태 전이 콜백에서 부수 잡 생성(예: update_associated_deviations_in_worker의 FlushDeviationCaptureStateWorker.perform_at)만 남기고 무거운 로직은 별도 워커로 분리. 이미 대부분 그렇게 되어 있으므로 잔여 사례 감사.
• 명시적 with_lock 도입 검토 — 짧은 명시적 lock(예: capture.with_lock { capture.update!(analysis_state: :processing) })으로 대기 시간을 예측 가능하게 만들고, 실패 시 즉시 backoff 재시도.

Monitoring#

기존 Sidekiq/Rails 대시보드에서 확인 가능한 항목 위주. 재현 가능한 Datadog 쿼리:

• 동일 fingerprint 재발생 추적:

  textCopy

  service:cupixworks-worker status:error @environment:production "AnalyzePanoWorker::perform" "Lock wait timeout"
  

• Capture 상태 전이 파이프라인의 최근 락 경합 전반:

  textCopy

  service:cupixworks-worker status:error @environment:production "Mysql2::Error::TimeoutError"
  

• AnalyzePanoWorker 성공/실패 비율 시계열:

  textCopy

  service:cupixworks-worker @environment:production @class:AnalyzePanoWorker
  

알람 제안: 위 첫 번째 쿼리 결과가 15분 창에서 5건 이상이면 알람 (지금은 1건).

Risk Assessment#

• Risk level: low — 단일 발생, 재시도로 자동 복구, 다른 파이프라인에 파급 없음, DB 정상.
• 예상 복잡도: trivial — 즉시 조치는 없음. 로그 레벨 조정 정도가 최소 개선.