ES /docs

Capture aggregate lock contention — concurrent worker updates

RCA: CapturesController#process_output_upload_url Latency Spike (2146ms)

Overview#

What Happened#

2026-05-26 08:22:05 UTC에 cupixworks-api 서비스의 Api::V1::CapturesController#process_output_upload_url 엔드포인트에서 단일 요청이 2146ms의 응답 시간을 기록했다. 해당 엔드포인트의 일반적인 응답 시간은 200-300ms이며, 이번 spike는 평균 대비 약 7-10배 느린 이상치이다.

Quick Facts#

Field Value
resource_name Api::V1::CapturesController#process_output_upload_url
top_frame app/repositories/concerns/process_outputable_repository.rb:5-6
env production, us-west-2
avg_duration 2146ms (평상시 200-300ms)

Timeline#

  1. 2026-05-26 17:22:06 KST — Capture 702529에 대한 update 요청 처리
  2. 2026-05-26 17:22:05-08 KST — 동일 capture에 대한 process_output_upload_url 요청 (2146ms 소요)
  3. 2026-05-26 17:22:08 KST — 첫 번째 process_output_upload_url 완료
  4. 2026-05-26 17:22:10 KST — 두 번째 process_output_upload_url 요청 완료
  5. 2026-05-26 17:22:11 KST — check_process_output_uploading 호출 (200)
  6. 2026-05-26 17:22:12 KST — finalization 시작, editing entity 생성

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::CapturesController#process_output_upload_url",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 2146,
  "max_ms": 2146,
  "sample_trace_id": "8918016138081072555"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1
  • 최초 발생: 2026-05-26T08:22:05.766Z
  • 최근 발생: 2026-05-26T08:22:05.766Z

영향 범위는 단일 요청에 제한되며, 사용자에게 약 2초의 추가 대기 시간이 발생한 수준. 기능적 오류는 없음 (HTTP 200 반환).

Root Cause Summary#

동일 capture (ID: 702529)에 대해 update와 process_output_upload_url 요청이 거의 동시에 도착하여 PostgreSQL row-level lock contention이 발생했다. process_output_upload_url 요청은 @model.save 실행 시 동일 레코드를 업데이트 중인 update 트랜잭션이 커밋될 때까지 대기해야 했으며, 이로 인해 약 1.8-1.9초의 추가 지연이 발생했다. Capture 모델의 sys JSON 컬럼을 두 요청이 동시에 수정하려는 패턴이 근본 원인이다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/concerns/process_outputable_controller.rb:4
  • set_capture before_action → CaptureRepository#show (DB SELECT)
  • repository_instance.process_output_upload_url → app/repositories/concerns/process_outputable_repository.rb:4-7
  • change_process_output_state('uploading') → sys[:process_output][:state] = 'uploading' (in-memory)
  • @model.save → DB UPDATE + callbacks (여기서 lock 대기 발생)
  • Serializer: model.process_output_upload_url → S3 presigned URL 생성 (로컬 서명, 네트워크 호출 없음)
app/repositories/concerns/process_outputable_repository.rb:4-7ruby
def process_output_upload_url
  @model.change_process_output_state('uploading')
  @model.save
  @model
end
app/models/concerns/process_outputable/capture.rb:39-42ruby
def change_process_output_state(state)
  self.sys[:process_output] ||= {}
  self.sys[:process_output][:state] = state
end

save 호출 시 sys JSONB 컬럼 전체가 UPDATE된다. 동시에 다른 트랜잭션이 같은 row의 sys 컬럼을 수정 중이라면 PostgreSQL의 row-level lock에 의해 대기가 발생한다.

app/models/concerns/stale_review/capture.rb:10-11ruby
around_save :touch_reviews_after_save, unless: :skip_touch_reviews?
after_save :touch_record_after_save, unless: :skip_touch_reviews?

추가적으로 save 시 around_save 콜백으로 인해 트랜잭션 범위가 확장되고, lock 보유 시간이 길어질 수 있다.

Log Evidence#

Datadog에서 확인된 동시 요청 패턴:

text
service:cupixworks-api "702529" from:2026-05-26T08:21:00Z to:2026-05-26T08:23:00Z
text
2026-05-26 17:22:06 KST [200] PUT /api/v1/captures/702529 (Api::V1::CapturesController#update)
2026-05-26 17:22:08 KST [200] POST /api/v1/captures/702529/process_output_upload_url
2026-05-26 17:22:10 KST [200] PUT /api/v1/captures/702529 (Api::V1::CapturesController#update)
2026-05-26 17:22:10 KST [200] POST /api/v1/captures/702529/process_output_upload_url
2026-05-26 17:22:11 KST [200] PUT /api/v1/captures/702529/check_process_output_uploading
2026-05-26 17:22:12 KST [400] PUT /api/v1/captures/702529/check_process_output_uploading (Invalid state: uploaded)

동일 capture에 대해 2초 내에 update 2회, process_output_upload_url 2회가 연속 호출되었다. 첫 번째 process_output_upload_url (17:22:05 시작 → 17:22:08 응답, ~2.1초)이 바로 latency spike에 해당한다.

APM 메트릭에서 확인된 일반적인 응답 시간:

text
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::capturescontroller_process_output_upload_url} over 24h
→ 평균 200-300ms (0.20s ~ 0.33s)

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 동일 row에 대한 concurrent UPDATE로 인한 PostgreSQL row-level lock contention 동일 capture 702529에 대해 update와 process_output_upload_url이 동시 호출된 로그 확인. 두 요청 모두 sys JSONB 컬럼을 수정. 응답 시간 2146ms는 lock 대기 시간으로 설명 가능 slow query 로그 미발견 (error level만 기록됨) Confirmed
H2 S3 presigned URL 생성 시 네트워크 지연 presigned URL 생성은 외부 서비스 호출 포함 가능 Aws::S3::Object#presigned_url은 로컬 서명만 수행 (STS 호출 없음). 네트워크 I/O 불필요. 코드 확인: process_output_object.presigned_url(:put, ...) Rejected
H3 save 시 counter_culture 콜백으로 인한 추가 DB 쿼리 지연 Capture 모델에 10개 이상의 counter_culture 설정 존재 counter_culture는 execute_after_commit: true로 설정되어 있어 트랜잭션 내에서 추가 쿼리를 발생시키지 않음. process_output_state 변경은 counter 조건에 해당하지 않음 Rejected
H4 GC pause 또는 Ruby VM 일시 중단 단일 요청에서만 발생한 이상치 GC pause는 보통 100ms 미만. 2146ms는 GC로 설명하기 어려움. 동시 호출 로그가 lock contention과 더 일치 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

해당 이슈는 단일 발생(1회)이며 사용자 영향이 미미한 수준이므로 즉시 조치가 필요하지 않다.

단기 개선 (1주 이내)#

  • process_outputable_repository.rb:4-7에서 save 호출 시 sys 컬럼만 선택적으로 업데이트하도록 변경 (update_column 또는 partial update)하여 lock 범위를 축소하는 방안을 검토.
  • 클라이언트 측에서 동일 capture에 대한 process_output_upload_url과 update의 동시 호출을 직렬화하는 것을 검토.

장기 개선 (재발 방지)#

  • sys JSONB 컬럼에 여러 도메인(process_output, storage_option, previous_record_id 등)의 상태를 함께 저장하는 구조가 lock contention의 근본 원인. 도메인별로 별도 컬럼 또는 테이블로 분리하면 concurrent update 시 충돌 범위가 줄어든다.
  • around_save 콜백 체인이 트랜잭션을 불필요하게 길게 유지할 수 있으므로, write-heavy 엔드포인트에서는 콜백 최소화를 검토.

Monitoring#

  • process_output_upload_url 엔드포인트의 p99 latency를 모니터링하는 APM monitor 추가:
text
avg(last_5m):trace.rack.request.duration.by.resource_name{service:cupixworks-api,resource_name:api::v1::capturescontroller_process_output_upload_url} > 2
  • PostgreSQL lock wait 이벤트를 추적하기 위한 pg_stat_activity 기반 메트릭 추가 검토.

Risk Assessment#

  • Risk level: low
  • 예상 복잡도: trivial

단일 발생이며 기능 오류 없이 응답 지연만 발생. 동시 요청 패턴이 일상적이지 않아 재발 빈도 낮음.