RCA: Api::V1::FacilitiesController#update_spacetime latency (12.68 s)

Overview#

What Happened#

2026-07-09 09:59 KST에 cupixworks-api 서비스에서 Api::V1::FacilitiesController#update_spacetime 요청 1건이 12681 ms 동안 실행되었다. 정상 요청은 대부분 서브초 수준에서 완료되지만, 같은 시간대에 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 가 PanosController, JobsController, CapturesController 등 여러 엔드포인트에서 다발적으로 발생했으며, 이번 요청은 InnoDB row lock 대기로 응답이 지연된 것으로 판단된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-09 09:32 KST — POST /api/v1/panos 첫 Lock wait timeout 발생 (Datadog error 로그).
2. 2026-07-09 09:45~09:56 KST — PUT /api/v1/panos/*/meta/blurriness, check_tile_uploading, captures/* 등에서 502 lock timeout 반복.
3. 2026-07-09 09:59:43 KST — PUT /api/v1/facilities/zvizoq/spacetimes/1488237 요청 시작 (trace 2565454549763153544).
4. 2026-07-09 09:59:56 KST — 같은 요청이 HTTP 200으로 완료. 총 12.68 s 소요.
5. 2026-07-09 10:01~10:03 KST — JobsController#update, PanosController#check_uploading 등에서 502 lock timeout 4건 추가.
6. 2026-07-09 10:04 KST 이후 — lock timeout 로그가 사라지고 트래픽 정상화.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FacilitiesController#update_spacetime",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 12681,
  "max_ms": 12681,
  "sample_trace_id": "2565454549763153544"
}

같은 시간대의 대표적 lock timeout 로그 (Datadog):

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

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (slow trace), 다만 같은 창에서 별도로 15건 이상의 LockWaitTimeout 발생
• 최초 발생: 2026-07-09 09:59 KST
• 최근 발생: 2026-07-09 09:59 KST

Root Cause Summary#

Api::V1::FacilitiesController#update_spacetime 는 FacilityRepository#update_spacetime 을 통해 spacetime.save! 를 호출한다. 이번 요청이 12.68 s 걸린 이유는 동일 시간대에 발생한 광범위한 MySQL InnoDB lock 경합 때문으로 판단된다. Datadog error 로그를 보면 09:32~10:03 KST 사이에 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 가 panos, captures, jobs, spacetimes 관련 다수 엔드포인트에서 동시에 발생했고, 서비스 전체 max:trace.rack.request.duration 도 같은 창에서 최대 2352 s 까지 튀었다. 즉 이 요청은 특정 spacetime row에 대한 InnoDB row lock 을 기다리다가 다른 트랜잭션이 커밋된 뒤(또는 부분적으로 풀린 뒤) 저장에 성공하여 200 을 반환한 것이다. 요청 자체의 payload 검증 로직(validate_summary!, validate_summary_vector_embedding!)이나 3072차원 벡터(약 21 KB) 직렬화만으로 12 s 지연이 나올 수 없으며, 로그와 코드에는 동기 외부 호출도 없다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/facilities_controller.rb:61 (def update_spacetime)
• Repository dispatch: app/repositories/facility_repository.rb:122 (def update_spacetime)
• Failure point (지연 지점): app/repositories/facility_repository.rb:143 (spacetime.save!)

Controller 는 요청을 그대로 repository 로 위임한다:

def update_spacetime
  spacetime = repository_instance.update_spacetime(params[:spacetime_id], params)

  render_api Renderable.new({
    contents: spacetime,
    serializer: SpacetimeSerializer,
    serializer_option: {
      fields: {
        spacetime: @fields
      }
    }
  })
end

Repository 는 spacetime 을 로드하고, summary 검증 → 대입 → save! 를 실행한다:

def update_spacetime(spacetime_id, params)
  raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied') unless self.model.updatable_by?(self.current_user)

  spacetime = @model.spacetimes.find_by(id: spacetime_id)
  raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: 'Spacetime not found') if spacetime.nil?

  if params[:summary].present?
    summary = params[:summary].is_a?(ActionController::Parameters) ? params[:summary].permit!.to_h : params[:summary]
    spacetime.validate_summary!(summary)
    spacetime.summary = summary
    spacetime.summary_text = spacetime.summary_text_for_search
  end

  spacetime.summary_state = params[:summary_state] if params.key?(:summary_state)

  if params.key?(:summary_vector_embedding)
    spacetime.validate_summary_vector_embedding!(params[:summary_vector_embedding])
    spacetime.summary_vector_embedding = params[:summary_vector_embedding]
  end

  begin
    spacetime.save!
  rescue StandardError => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
  end

  spacetime
end

Spacetime 모델에는 write 계열 callback 이 거의 없다. 유일한 콜백 concern 인 Cachable::ReviewLoad 는 create/destroy 만 걸려 있어 update 경로에는 영향이 없다:

included do
  after_create :invalidate_facility_review_cache_on_create
  after_destroy :invalidate_facility_review_cache_on_destroy
end

spacetimes 테이블은 다수의 counter cache 컬럼(captures_count, pointclouds_count, published_captures_count 등)을 가지며, 자식 모델(Capture, Pointcloud, Mesh)이 활발하게 write 하면 같은 spacetime row 를 counter_culture 로 갱신한다. 따라서 이 update 는 자식 write 트랜잭션이 잡고 있는 row lock 을 기다리게 된다:

create_table "spacetimes", charset: "utf8mb4", collation: "utf8mb4_unicode_ci", force: :cascade do |t|
  t.integer "captures_count", default: 0, null: false
  # ... 다수 counter cache 컬럼 ...
  t.json "summary"
  t.string "summary_state", default: "none", null: false
  t.text "summary_text"
  t.json "summary_vector_embedding"
  t.bigint "team_id"
  # ...
end

기대 동작: spacetime.save! 는 서브초 안에 완료된다 (다른 성공 로그의 트래픽 리듬으로 확인 가능 - 10:00:30 ~ 10:02:21 사이 정상 200 응답 다수).

실제 동작: 09:59:43 KST 에 시작한 요청이 12.68 s 지속되었고, 같은 창에 다른 write endpoint 들이 동일 원인(Lock wait timeout) 으로 502 를 반환했다. 이 요청은 lock 을 확보한 뒤 성공적으로 커밋되어 HTTP 200 을 반환한 케이스로 해석된다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "update_spacetime"
service:cupixworks-api "spacetimes/1488237"
service:cupixworks-api "LockWaitTimeout" OR "Lock wait"

해당 slow trace 에 대응하는 액세스 로그 (요청 완료 시각):

2026-07-09 09:59:56 KST  info  [200] PUT /api/v1/facilities/zvizoq/spacetimes/1488237 (Api::V1::FacilitiesController#update_spacetime)
2026-07-09 09:58:13 KST  info  [200] GET /api/v1/facilities/zvizoq/spacetimes/1488237 (Api::V1::FacilitiesController#show_spacetime)

동일 시간창의 lock timeout (요약):

2026-07-09 09:32:10 KST  [500] POST /api/v1/panos                                Mysql2::Error::TimeoutError: Lock wait timeout exceeded
2026-07-09 09:45:52 KST  [502] PUT  /api/v1/panos/92616351/meta/blurriness       Lock wait timeout exceeded
2026-07-09 09:47:06 KST  [502] PUT  /api/v1/panos/92616351/meta/blurriness       Lock wait timeout exceeded
2026-07-09 09:48:34 KST  [502] PUT  /api/v1/panos/92616351/meta/blurriness       Lock wait timeout exceeded
2026-07-09 09:49:21 KST  [502] PUT  /api/v1/panos/92616644/check_tile_uploading  Lock wait timeout exceeded
2026-07-09 09:50:15 KST  [502] PUT  /api/v1/panos/92616644/check_tile_uploading  Lock wait timeout exceeded
2026-07-09 09:56:02 KST  [502] PUT  /api/v1/captures/730522                      Lock wait timeout exceeded
2026-07-09 10:01:41 KST  [502] PUT  /api/v1/jobs/1182736/actions/postprocessor/complete  Lock wait timeout exceeded
2026-07-09 10:01:56 KST  [502] PUT  /api/v1/jobs/1182655/actions/postprocessor/complete  Lock wait timeout exceeded
2026-07-09 10:02:15 KST  [502] PUT  /api/v1/jobs/1182934                         Lock wait timeout exceeded
2026-07-09 10:02:37 KST  [502] PUT  /api/v1/jobs/1182736/actions/postprocessor/complete  Lock wait timeout exceeded
2026-07-09 10:02:47 KST  [502] PUT  /api/v1/jobs/1182655/actions/postprocessor/complete  Lock wait timeout exceeded
2026-07-09 10:02:59 KST  [502] PUT  /api/v1/panos/92631059/check_uploading       Lock wait timeout exceeded
2026-07-09 10:03:03 KST  [502] PUT  /api/v1/panos/92631090/check_uploading       Lock wait timeout exceeded
2026-07-09 10:03:07 KST  [502] PUT  /api/v1/jobs/1182934                         Lock wait timeout exceeded

서비스 전체 max:trace.rack.request.duration{service:cupixworks-api} 지표(24 h 창) 는 최근 24 시간 중 다수 구간에서 60220 s 로 상승했고, 특정 구간에서는 1824 s, 1913 s, 2352 s 스파이크가 관측된다. 정상 구간은 818 s 수준으로, 이번 이벤트 시점의 스파이크는 명확한 이상치다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 코드 변경 없음. 이번 클러스터는 광범위한 DB lock 경합의 부수 효과이며, 코드 결함이 아니다.
• spacetimes/{id} 를 갱신하는 caller (Capture Intelligence agent, applications/agents/* 의 compass-capture_summary 후속 작업) 가 lock timeout 발생 시 재시도하는지 확인. 재시도가 없으면 idempotent 재시도(exponential backoff, jitter) 추가를 검토한다.

단기 개선 (1주 이내)#

• 09:30~10:05 KST 창에서 spacetimes/panos/captures row 를 물고 있던 장기 트랜잭션을 특정. 후보:
  • postprocessor/complete 액션이 counter cache 및 자식 rows 를 대량 갱신하며 spacetime row 를 함께 잠금.
  • Sidekiq 워커(counter_culture recount, batch update)가 spacetime 계열 row 를 오래 잠금.
• InnoDB information_schema.INNODB_TRX, INNODB_LOCK_WAITS, SHOW ENGINE INNODB STATUS 기록을 아카이브하는 스크립트 유무 확인. 없으면 lock 경합 재현 시 15초 간격 덤프를 남기는 cron 도입.
• Api::V1::FacilitiesController#update_spacetime 응답이 5 s 초과할 때 warn 로그를 남기도록 slow endpoint alert 를 도입해, lock 대기 상황이 사용자 응답 지연으로 이어질 때 조기 감지.

장기 개선 (재발 방지)#

• spacetimes 테이블의 잦은 counter cache 갱신을 분리 큐/배치 집계로 옮기는 방안 검토. 현재 스키마는 20 개 이상의 counter 컬럼을 실시간으로 유지하도록 되어 있어, 같은 row 에 대한 write 접점이 많다.
• Capture Intelligence 흐름은 SQS FIFO 로 spacetime 별 직렬화되어 있으나(문서: docs/reference/capture-intelligence.md), 해당 spacetime row 는 여전히 postprocessor/complete 같은 다른 엔드포인트와 lock 을 공유. summary/embedding 만 update 하는 얇은 경로에 update_columns 또는 no_touching 옵션 고려로 자식 counter 갱신과 경합을 축소.
• 서비스 전체 Lock wait timeout 이벤트를 SLO/alert 로 대시보드화하여, 이런 다발 경합이 발생하는 시간대 자체를 인시던트로 인식하도록 한다.

Monitoring#

핵심 지표: (1) 이 엔드포인트의 p95 duration, (2) 서비스 전체 lock wait 발생 rate.

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::facilitiescontroller.update_spacetime}

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::facilitiescontroller.update_spacetime}.as_rate()

Lock wait timeout 이벤트 rate (로그 기반 metric 등록 후 사용):

sum:logs.hits{service:cupixworks-api,message:"Lock wait timeout"}.as_count()

전체 서비스 slow request 상한:

max:trace.rack.request.duration{service:cupixworks-api}

Risk Assessment#

• Risk level: medium — 사용자 요청은 성공했지만 12 s 지연은 실사용자 경험을 저해하며, 같은 창에서 다른 write API 가 502 로 실패했다. 재발 시 Capture Intelligence 파이프라인 지연/에러가 발생할 수 있다.
• 예상 복잡도: standard — 단일 endpoint 수정보다 DB 경합 원인(어느 트랜잭션이 lock 을 오래 유지했는지) 규명이 우선이며, 이는 InnoDB trx/log 분석이 필요하다.