RCA: Api::V1::ClustersController#resource_upload_url latency spike (16.9s)

Overview#

What Happened#

2026-07-11 04:20 KST 시점에 cupixworks-api (us-west-2, tenant cupix) 의 POST /api/v1/clusters/:id/resources/:kind/upload_url 요청 한 건이 16,942 ms 동안 지속된 뒤 정상(HTTP 200)으로 완료되었다. 동일한 시간대(UTC 18:15–19:37, KST 03:15–04:37) 에 다른 PUT 계열 엔드포인트(Api::V1::JobsController#update, #complete_action, Api::V1::PanosController#check_uploading, check_tile_uploading, update_meta_by_key, Api::V1::PointcloudsController#check_uploading) 에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 예외가 50건 이상 관측되었다. 이 latency span 은 DB row lock 경합으로 인한 대기시간의 일부이며, innodb_lock_wait_timeout 만료 전에 잠금을 획득해 성공한 케이스로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-11 03:15 KST — Api::V1::PanosController#update_meta_by_key, #check_tile_uploading, Api::V1::JobsController#complete_action 등에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 가 반복 발생 (UTC 18:15Z).
2. 2026-07-11 04:20:39 KST — 문제의 span 발생. POST /api/v1/clusters/.../resources/.../upload_url 이 16,942 ms 소요 후 200 응답 (UTC 19:20:39Z).
3. 2026-07-11 04:23–04:37 KST — Api::V1::JobsController#update 요청 다수가 LockWaitTimeout 로 502 실패 (UTC 19:23–19:37Z).
4. 이후 — Datadog 상에서 정상 응답 시간(수백 ms 수준)의 resource_upload_url 요청이 다시 정상적으로 처리됨.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ClustersController#resource_upload_url",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 16942,
  "max_ms": 16942,
  "sample_trace_id": "8628019757318599716"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (>500ms 필터 기준 span)
• 최초 발생: 2026-07-11 04:20 KST
• 최근 발생: 2026-07-11 04:20 KST

Root Cause Summary#

Api::V1::ClustersController#resource_upload_url 는 MultipleResourcableController#resource_upload_url 에서 @resource.upload_url 을 호출하고, 이는 다시 Storagable::Resource#upload_url 에서 state_machine 이벤트 self.uploading 을 발생시켜 resources 테이블에 UPDATE 를 수행한다. 이 UPDATE 는 대상 row 에 대한 InnoDB row-level exclusive lock 을 필요로 한다. 동시간대에 다른 트랜잭션(예: JobsController#complete_action, PanosController#check_uploading 등 업로드 완료/상태 갱신 계열)이 관련 row 를 오래 잠그고 있어 이번 요청은 16.9 초 동안 잠금을 기다린 후 획득에 성공했다. 같은 시간대의 50+ 건 502 LockWaitTimeout 은 잠금을 획득하지 못한 형제 요청들이며, 본 span 은 잠금 대기가 innodb_lock_wait_timeout (일반적으로 50s) 만료 이전에 해소되어 성공한 케이스이다. 즉, 코드 자체의 버그가 아닌 DB row lock 경합이 근본 원인이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/clusters_controller.rb:1 (Api::V1::ClustersController, include MultipleResourcableController at line 10)
• Handler: app/controllers/concerns/multiple_resourcable_controller.rb:110 (#resource_upload_url)
• Model event: app/models/concerns/storagable/resource.rb:101 (Storagable::Resource#upload_url)
• State transition: app/models/concerns/statable/resource.rb:18 (event :uploading do transition all => :uploading end)
• S3 signing: app/models/concerns/storagable/resource.rb:111 (#presigned_upload_url)

def resource_upload_url
  case @resource.state_name
  when :created, :uploading, :missing, :done, :error
    @resource.upload_url
  else
    raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: "Invalid resource state: #{@resource.state}")
  end
rescue Cupix::Errors::Parameter => e
  raise e
else
  render_api Renderable.new({
    contents: @resource,
    serializer: ResourceSerializer,
    serializer_option: {
      fields: {
        resource: @fields
      },
      is_collection: false
    }
  })
end

def upload_url(revision = nil, **kwags)
  self.uploading unless self.uploading?         # ← state_machine event → UPDATE resources SET state='uploading'
  self.presigned_upload_url(revision, force: kwags[:force])
end

# ...

def presigned_upload_url(revision, force: false)
  revision ||= self.revision + 1

  if !force && revision < self.revision
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: "Invalid revision: #{revision}")
  end

  client = Cupix::StorageService.client(storage_option: storage_option)
  signer = Aws::S3::Presigner.new(client: client)
  bucket_name = storage_option.s3_source_bucket_name
  expires_in = 2.hour.to_i

  signer.presigned_url(
    :put_object,
    bucket: bucket_name,
    key: object(revision).key,
    storage_class: 'ONEZONE_IA',
    expires_in: expires_in,
    acl: 'bucket-owner-full-control'
  )
end

state_machine initial: :created do
  # State
  state :created, :uploading, :missing, :processing, :done, :error do
  end

  event :created do
  end

  event :uploading do
    transition all => :uploading      # ← always writes to DB even if already :uploading (mitigated by `unless self.uploading?` in caller)
  end
  # ...
end

기대 동작: 정상적인 경우 self.uploading 은 수 ms 내에 resources row 를 UPDATE 하고, Aws::S3::Presigner 로 pre-signed URL 을 즉시 생성해 총 100–500ms 수준으로 응답한다. 실제로 인접 시간대의 다른 resource_upload_url 로그는 지연 없이 성공하고 있다 (아래 Log Evidence 참고).

실제 동작: 같은 시각 다른 트랜잭션이 관련 row (또는 상위 리소스 row) 에 exclusive lock 을 보유하고 있어 self.uploading 의 UPDATE 가 잠금 대기에 걸림. 16.9 초 후 잠금이 해제되어 UPDATE 가 성공하고, S3 서명 후 200 반환. 같은 시간대 다른 요청들은 innodb_lock_wait_timeout 만료로 Mysql2::Error::TimeoutError 를 받아 502 로 실패.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "Api::V1::ClustersController#resource_upload_url"
  (2026-07-10T18:00:00Z → 2026-07-10T20:00:00Z)

service:cupixworks-api "Lock wait timeout"
  (2026-07-10T18:00:00Z → 2026-07-10T20:00:00Z)

동일 시간대에 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 가 여러 엔드포인트에서 반복 관측됨:

{
  "timestamp": "2026-07-11 04:23:21 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/jobs/1188565 (Api::V1::JobsController#update)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

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

{
  "timestamp": "2026-07-11 03:23:13 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/jobs/1188369/actions/postprocessor/complete (Api::V1::JobsController#complete_action)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

문제의 span 시각(04:20:39 KST) 전후 Api::V1::ClustersController#resource_upload_url 로그는 200 응답이며, 시간대 앞뒤로 다수의 요청이 큰 지연 없이 처리되고 있음이 확인됨 — 즉, 본 latency 는 지속적 성능 저하가 아닌 일시적 lock 경합의 산물이다:

2026-07-11 04:20:57 KST [200] POST /api/v1/clusters/1444621/resources/preview_image/upload_url
2026-07-11 04:23:13 KST [200] POST /api/v1/clusters/1444731/resources/preview_image/upload_url
2026-07-11 04:26:37 KST [200] POST /api/v1/clusters/1444528/resources/preview_image/upload_url

Status board (svc:cupixworks-api::unknown) 조회 결과 동일 서비스에서 2026-07-06 이후로 “cupixworks-api service degraded” 인시던트가 7건 반복 발생했으며 (직전 인시던트 2026-07-10-svc-cupixworks-api--unknown-4 는 UTC 18:18–18:43Z 에 6개 클러스터를 묶었다), 이는 본 이슈가 간헐적으로 재발하는 DB 부하/lock 경합 패턴임을 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도의 코드 변경 없이도 자동 복구된 사례이지만, 재발 감시가 즉시 필요하다. status board 상 svc:cupixworks-api::unknown 인시던트가 최근 5일간 7회 반복되었으므로, 아래 Monitoring 섹션 쿼리를 대시보드에 추가.
• Storagable::Resource#upload_url (app/models/concerns/storagable/resource.rb:101-104) 의 무조건적 self.uploading 호출은 이미 unless self.uploading? 가드가 있음. 다만 state_machine 이벤트가 항상 transition all => :uploading 이라 이미 uploading 상태에서도 트리거되면 UPDATE 를 유발 (statable/resource.rb:19). 이 재입력 UPDATE 를 정말로 피하고 싶다면 이벤트 정의를 transition all - [:uploading] => :uploading 으로 좁힐 수 있으나, unless self.uploading? 가드로 이미 방지되므로 우선순위는 낮음.

단기 개선 (1주 이내)#

• Long-running transaction 을 찾아 원인 트랜잭션을 특정한다. 후보:
  1. Api::V1::JobsController#complete_action (postprocessor/complete) — 502 로그에서 반복 실패. 이 액션이 다수의 resources/panos/pointclouds row 를 하나의 트랜잭션 안에서 UPDATE 하고 있을 가능성.
  2. Api::V1::PanosController#check_uploading, #check_tile_uploading, #update_meta_by_key — 모두 502 발생. 배치 형태로 대량 호출될 때 트랜잭션이 길어질 수 있음.
• MySQL SHOW ENGINE INNODB STATUS / information_schema.INNODB_TRX 스냅샷을 인시던트 발생 시점 자동 수집하는 hook 을 추가해 lock holder 파악을 자동화.
• resource_upload_url 은 idempotent 한 URL 발급 API 이므로, self.uploading 이 이미 :uploading 상태이면 UPDATE 스킵하도록 state_machine 이벤트 정의를 transition all - [:uploading] => :uploading 으로 조정해 불필요한 row lock 획득 자체를 줄이는 방안 검토 (app/models/concerns/statable/resource.rb:18-20). 이미 Storagable::Resource#upload_url 이 unless self.uploading? 로 감싸고 있어 실질 영향은 제한적이나, 다른 호출 경로(예: upload_credentials in multiple_resourcable_controller.rb:132-141) 에는 이 guard 가 없음.

장기 개선 (재발 방지)#

• 트랜잭션 경계 축소: #complete_action, #check_uploading 계열에서 트랜잭션 내부에서 수행하는 S3/외부 I/O 를 트랜잭션 밖으로 빼고, 다수 row 갱신은 배치 UPDATE 로 재작성해 트랜잭션 유지 시간을 줄인다.
• 읽기 전용 fast path: resource_upload_url 이 반드시 상태 전이를 유발해야 하는지 재검토. presigned URL 발급 자체는 상태 없이도 가능하며, state 는 클라이언트가 실제 업로드를 시작한 시점(check_uploading) 에 갱신해도 무방해 보인다. 이 변경을 하면 GET 스타일 URL 발급이 완전히 DB 쓰기 없이 처리 가능.
• Status board 반복 svc:cupixworks-api::unknown 인시던트 (7회/5일) 를 종합해 별도의 DB lock 경합 후속 RCA 를 진행. 본 span 은 그 증상 중 하나일 뿐.

Monitoring#

Datadog 릴리즈 대시보드용 timeseries widget 쿼리 (모두 writing-datadog-monitoring-queries skill 기준의 timeseries-safe 문법):

• resource_upload_url p95/p99 응답시간 (spike 재발 감지):

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::clusterscontroller#resource_upload_url}

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::clusterscontroller#resource_upload_url}

• Lock wait timeout 발생률 (근본 원인 추적용):

sum:trace.rack.request.errors{service:cupixworks-api,error_type:activerecord::lockwaittimeout}.as_count()

• Storagable resource UPDATE 지연 대체 지표 (Rails 전체 request 오류 비율):

sum:rails.request.errors{service:cupixworks-api}.as_rate()

• 참고: DB 측 지표가 있다면 (RDS/mysql integration) 아래도 함께 대시보드에 추가:

avg:mysql.innodb.row_lock_time{service:cupixworks-api}

avg:mysql.innodb.row_lock_waits{service:cupixworks-api}.as_rate()

Risk Assessment#

• Risk level: medium (단일 span 은 200 이지만, 같은 근본 원인으로 인한 502 가 다수 발생. 서비스 저하가 5일 내 7회 재발 중).
• 예상 복잡도: standard (즉시 조치는 모니터링 추가 및 후속 RCA. 트랜잭션 경계 축소 등 근본 수정은 별도 티켓 필요).