RCA: Api::V1::PointcloudsController#check_cpc_mesh_uploading (avg 50899ms, max 51359ms)

Overview#

What Happened#

2026-07-09 11:24 KST 경 cupixworks-api production 환경에서 pointcloud 1210226 를 대상으로 한 PUT /api/v1/pointclouds/:id/check_cpc_mesh_uploading 요청 2건이 각각 약 50.9초와 51.4초 지속되다가 ActiveRecord::LockWaitTimeout (Mysql2::Error::TimeoutError: Lock wait timeout exceeded) 으로 502 응답을 반환했다. 두 요청 모두 동일 pointcloud row 에 대한 다른 트랜잭션이 lock 을 보유하는 동안 InnoDB innodb_lock_wait_timeout (기본 50초) 을 초과했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-09 11:23:14 KST — Pointcloud 1210226 state initializing → queued 로 전환
2. 2026-07-09 11:23:16–11:23:19 KST — 클라이언트가 check_uploading, check_octree_uploading, cpc_mesh_upload_url, update, resources, create_potree_upload_credentials 등 동일 pointcloud 에 대한 다수 PUT/POST 를 짧은 간격으로 발행
3. 2026-07-09 11:24:23 KST — first_seen. 첫 check_cpc_mesh_uploading 요청이 pointclouds row 의 lock 을 기다리기 시작 (Datadog trace 1703288425810257413)
4. 2026-07-09 11:25:15 KST — 첫 502 응답 (Lock wait timeout exceeded, 51.4초 소요)
5. 2026-07-09 11:25:46 KST — Postprocess 진행 중 (potree_upload_credentials 200 응답)
6. 2026-07-09 11:26:08 KST — 두 번째 502 응답 (동일 에러, 50.9초 소요) — 이 시점이 last_seen
7. 2026-07-09 11:26:44 KST — Pointcloud state queued → done 로 전환, start_finalization 호출, editing entity 생성
8. 2026-07-09 11:26:45–46 KST — 이후 check_cpc_mesh_uploading 재폴링 200 성공, 클러스터 자연 해소

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PointcloudsController#check_cpc_mesh_uploading",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 50899,
  "max_ms": 51359,
  "sample_trace_id": "1703288425810257413"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-07-09 11:24 KST
• 최근 발생: 2026-07-09 11:25 KST
• Blast radius: Pointcloud 1210226 (tenant cupix) 업로드 확인 폴링 2회에 국한. 지난 14일 동안 check_cpc_mesh_uploading 에서 발생한 Lock wait timeout 은 이 두 건이 전부 (Datadog 확인)이며, 다른 pointcloud/tenant 로의 확산은 없음

Root Cause Summary#

check_cpc_mesh_uploading 요청이 실행되던 시점에 동일 pointcloud row (pointclouds.id = 1210226) 를 갱신 중인 다른 트랜잭션이 존재하여 ActiveRecord::LockWaitTimeout 이 발생했다. 이 endpoint 는 CpcMeshRepository#check_cpc_mesh_uploading 을 통해 S3 에서 mesh object 존재 여부를 확인 (Cupix::StorageService.object(...).exists?) 하고, uploaded 상태이면 state_machines gem 의 uploaded_cpc_mesh_state 이벤트를 발화한다. state_machines-activerecord 는 상태 저장 시 자동으로 ActiveRecord::Base.transaction 을 열고 save 를 수행하므로 pointclouds row 에 대한 UPDATE ... WHERE id = 1210226 쓰기 lock 이 필요하다. 로그 타임라인상 pointcloud 1210226 은 같은 시간대에 state, resource_state 등 다른 state machine 전이와 다수의 PUT update 호출을 동시 처리 중이었고, 이들 중 하나가 자기 트랜잭션 안에서 heavy callback chain (update_group_state, record.update_capture_editing_state, record.update_record_state, start_finalization) 을 실행하는 동안 row-level lock 을 InnoDB 기본 innodb_lock_wait_timeout=50s 를 초과하여 계속 붙들고 있었기 때문에 대기 중이던 check_cpc_mesh_uploading 트랜잭션이 timeout 으로 실패했다. 이 endpoint 는 read-only 성격의 폴링 (S3 존재 확인) 임에도 상태를 조건부로 갱신하기 위해 write transaction 을 시도하도록 구현되어 있어, 상위 처리 파이프라인이 lock 을 점유하는 동안 client 폴링이 502 를 유발한다.

Technical Analysis#

Code Path#

Entry point → repository → model → S3 → state machine save 순서.

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

def check_cpc_mesh_uploading
  case @model.cpc_mesh_state_name
  when :uploading
    raise Cupix::Errors::Resource.new(code: 'RESC10000', reason: 'CPC Mesh does not uploaded') unless @model.check_cpc_mesh_uploading
  else
    raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: "Invalid state: #{@model.cpc_mesh_state}")
  end

  @model
end

def check_cpc_mesh_uploading
  if cpc_mesh_uploaded?
    uploaded_cpc_mesh_state   # state_machines 이벤트 → pointclouds row UPDATE 트랜잭션
    true
  else
    false
  end
end

uploaded_cpc_mesh_state 는 state_machines gem 의 이벤트 메서드로, state_machines-activerecord integration 이 내부적으로 ActiveRecord::Base.transaction { self.cpc_mesh_state = ...; save } 를 수행한다. 이 지점이 pointcloud row 의 lock 을 획득하려다 대기하는 failure point 다.

병렬로 실행되는 state state machine 은 done 전이 시 무거운 callback chain 을 실행한다:

after_transition to: :done do |pointcloud, transition|
  # TODO: TSLA-4544 - initiate_editing_state will be removed after TSLA-4545 is implemented
  pointcloud.initiate_editing_state
  pointcloud.start_finalization
end

after_transition from: any, to: %I[uploaded processing error done queued] do |pointcloud, transition|
  pointcloud.update_group_state(transition.to)
  pointcloud.send("run_#{transition.to}_state_callbacks") if pointcloud.respond_to?("run_#{transition.to}_state_callbacks")
  true
end

after_transition do |pointcloud, transition|
  if pointcloud.respond_to?(:record)
    pointcloud.record.update_capture_editing_state
    pointcloud.record.update_record_state
  end
end

start_finalization 은 editing_entity 를 생성하고 finalization 워크플로를 시작한다:

def start_finalization
  is_editing_skip = self.try(:editing_skip?) || false

  if is_editing_skip
    Cupix::Logger.info("Editing skipped on #{self.class.name} #{id}", class: self.class.name, function: __method__)

    return
  end

  if (editing_entity_id.nil? || self.editing_entity&.editing.nil?) && respond_to?(:create_editing_entity)
    Cupix::Logger.info("create editing entity on start finalization #{self.class.name} #{id}", class: self.class.name, function: __method__)
    self.create_editing_entity
  end
  ...
end

기대 동작 vs 실제 동작:

• 기대: check_cpc_mesh_uploading 은 S3 확인 + 필요 시 상태 전이. 동시 요청이 많더라도 각 트랜잭션은 짧아야 함
• 실제: 다른 상태 전이 트랜잭션 (state=queued 처리, record 하위 콜백 등) 이 row lock 을 50초 이상 점유하여, 이를 기다리던 check_cpc_mesh_uploading 트랜잭션이 innodb_lock_wait_timeout=50s 를 초과하고 502 를 반환. first_seen (11:24:23) + 50s ≈ 11:25:13 은 첫 timeout 발생 시각 (11:25:15) 과 일치

Log Evidence#

Datadog query (재현 가능):

service:cupixworks-api "Lock wait timeout" "check_cpc_mesh_uploading"

시간 범위 now-14d ~ now 로 검색 시 아래 2건만 발견 — 클러스터 이벤트와 정확히 일치:

{
  "timestamp": "2026-07-09 11:25:15 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/pointclouds/1210226/check_cpc_mesh_uploading (Api::V1::PointcloudsController#check_cpc_mesh_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-07-09 11:26:08 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/pointclouds/1210226/check_cpc_mesh_uploading (Api::V1::PointcloudsController#check_cpc_mesh_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

같은 pointcloud 를 대상으로 한 컨텍스트 로그 (service:cupixworks-api 1210226, 2026-07-09T02:23:00Z–02:27:00Z):

11:23:14  pointcloud state changed from initializing to queued. id: 1210226
11:23:16  [200] PUT .../check_uploading
11:23:16  [200] POST .../octree_upload_url
11:23:18  [200] PUT .../check_octree_uploading
11:23:18  [200] PUT .../update
11:23:18  [200] GET  .../show
11:23:19  [200] POST .../cpc_mesh_upload_url
11:25:15  [502] PUT .../check_cpc_mesh_uploading   ← Lock wait timeout
11:25:46  [200] POST .../potree_upload_credentials
11:26:08  [502] PUT .../check_cpc_mesh_uploading   ← Lock wait timeout
11:26:44  pointcloud state changed from queued to done. id: 1210226
11:26:44  create editing entity on start finalization Pointcloud 1210226
11:26:45  [200] PUT .../check_cpc_mesh_uploading   ← 재시도 성공
11:26:46  [200] PUT .../check_cpc_mesh_uploading   ← 재시도 성공

• first_seen 11:24:23 KST + 50.9s → 11:25:14, 실제 첫 502 는 11:25:15 — innodb_lock_wait_timeout=50s default 와 정확히 일치
• 두 번째 요청은 첫 timeout 직후 재폴링, 다시 50.9s 대기 후 timeout (11:26:08)
• Pointcloud 1210226 이 queued → done 상태로 완결된 직후 (11:26:44) 재폴링은 200 으로 정상 응답 → row lock 이 그 시점에 해제됨을 확인
• 같은 시간대 다른 pointcloud / tenant 에서는 Lock wait timeout 이 없음 (해당 endpoint 기준). 시스템 전반 lock 병목이 아닌 단일 pointcloud 의 동시성 문제

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

즉시 코드 변경이 필요한 심각한 장애는 아니다 (2건, blast radius 단일 pointcloud, 클라이언트 재시도로 회복). 다만 short-term/long-term 개선을 진행하기 전까지 다음 monitoring alert 추가를 권장:

• service:cupixworks-api @error.class:ActiveRecord::LockWaitTimeout 알람 (임계치: 5분 내 3건 이상)

단기 개선 (1주 이내)#

app/models/concerns/cpc_mesh.rb:26-33 의 check_cpc_mesh_uploading 은 read-mostly 폴링 endpoint 이므로 쓰기 트랜잭션 진입을 최소화하도록 조정한다.

• cpc_mesh_uploaded? (S3 존재 확인) 은 이미 read-only. 문제 지점은 뒤이은 uploaded_cpc_mesh_state 상태 저장부.
• 개선 방향:
  1. 상태가 이미 :uploaded 인 경우 상태 전이 이벤트를 호출하지 않도록 guard 추가. cpc_mesh_state_name 을 조회해 이미 :uploaded 이면 no-op 로 반환. (state_machines 는 same-state transition 시에도 save 를 시도할 수 있음 — if: !cpc_mesh_state_uploaded? guard 필요)
  2. 상태 저장이 필요한 경우 별도 짧은 트랜잭션 (with_lock(timeout: 5) 또는 update_columns 로 callback 우회 검토) 을 사용해 다른 heavy transaction 과의 lock 대기를 짧게 종료. 단, callback 우회 시 update_group_state / record.update_* 가 필요하다면 별도 async job 으로 옮겨야 함.
• app/repositories/concerns/cpc_mesh_repository.rb:4-13 에서 상태가 :uploading 이 아닌 경우 InvalidState 를 raise 하는데, 재폴링 시 이미 :uploaded 로 넘어간 케이스에 대한 명확한 종료 상태 (200 with state: uploaded) 를 반환하도록 흐름을 다듬는 것도 도움이 됨.

장기 개선 (재발 방지)#

• Pointcloud state 전이의 after_transition callback chain (initiate_editing_state, start_finalization, update_group_state, record.update_capture_editing_state, record.update_record_state) 가 하나의 pointcloud row lock 하 트랜잭션에서 실행되고 있어, 무거워질 경우 클라이언트 폴링 등 다른 요청을 차단한다. 검토 항목:
  1. start_finalization 및 record 관련 하위 갱신을 after_commit + Sidekiq async job 으로 분리하여 트랜잭션 홀드 타임 단축
  2. update_group_state 처럼 다른 row 를 건드리는 콜백은 별도 transaction 으로 분리해 lock 획득 순서 통일 (deadlock 회피)
  3. Pointcloud upload/finalization 파이프라인 전체 성능 관측을 위해 각 state 전이 구간에 duration 메트릭 emit (pointcloud.state_transition.duration tag: from, to)
• 클라이언트 SDK 측 폴링 백오프 정책 (check_cpc_mesh_uploading 이 502 를 반환할 때 지수 백오프 + 상한 재시도) 이 이미 있는지 확인. 없다면 SDK 개선 검토.

Monitoring#

지속적 관측을 위한 Datadog 쿼리 (release dashboard timeseries widget 에 그대로 사용 가능한 형태):

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::pointcloudscontroller#check_cpc_mesh_uploading}.as_count()

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

ActiveRecord::LockWaitTimeout 발생 추이 (log-based metric 생성 후 사용 권장):

logs("service:cupixworks-api @error.class:ActiveRecord::LockWaitTimeout").index("*").rollup("count").by("resource_name")

메트릭이 아직 없다면, Datadog Logs 탐색용:

service:cupixworks-api @error.class:ActiveRecord::LockWaitTimeout

Alert 권장:

• ActiveRecord::LockWaitTimeout on cupixworks-api: 5분 rolling window 에서 3건 이상 → warning, 10건 이상 → critical
• resource_name:Api::V1::PointcloudsController#check_cpc_mesh_uploading 의 p95 latency > 5s (현 baseline 은 sub-second)

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 근거: 사고 규모는 2건, 단일 pointcloud, 클라이언트 재시도로 자연 회복. 그러나 근본 원인 (state machine transition 중 heavy callback chain 이 row lock 을 장기 점유) 은 다른 upload flow 에서 재발 가능성이 있으므로 monitoring 및 단기 개선 권장.