RCA: Api::V1::PanosController#show latency spike (11.6s)

Overview#

What Happened#

2026-07-03 07:03 KST에 cupixworks-api (us-west-2, tenant cupix) 의 GET /api/v1/panos/:id 요청 하나가 11,638ms 동안 블록되었다. Pano 단건 조회는 정상 상태에서 수십 ms 수준이지만, 같은 시각 다른 요청들이 대량의 MySQL Lock wait timeout exceeded 로 실패하고 있었고, 이 show 트랜잭션은 lock 대기열에 물려 innodb_lock_wait_timeout 직전까지 대기하다가 겨우 응답한 것으로 확인된다. 사이드보드가 같은 구간을 svc:cupixworks-api::unknown 인시던트(2026-07-02-svc-cupixworks-api--unknown-1)로 이미 그룹핑해 두었고, 이 클러스터는 그 인시던트의 세 이벤트 중 하나다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-03 06:57 KST — 사이드보드가 Api::V1::Admin::PointcloudsController#index 10s 지연으로 인시던트 오픈 (cluster e0e15b40-436b-4799-a616-6c51ef80e6f8).
2. 2026-07-03 07:03:15 KST — POST /api/v1/panos, PUT /api/v1/jobs/:id/actions/postprocessor/complete 에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 발생 시작. 07:03:15–07:03:38 KST 23초 동안 API 로그 상 lock wait 실패 30건 이상.
3. 2026-07-03 07:03:00 KST — 이 클러스터의 대상 요청 PanosController#show 시작, 11,638ms 후 응답 (trace_id 753922149806333051).
4. 2026-07-03 07:04:20 KST — 마지막 Lock wait timeout 로그. DB lock 압박 해소.
5. 2026-07-03 07:07:53 KST — TeamsController#invitation 45s 지연 (cluster cfc2776c-5d3d-4099-bba8-8d0348216461) — 인시던트 이벤트 3번째로 기록.
6. 2026-07-03 07:07:53 KST — 인시던트 2026-07-02-svc-cupixworks-api--unknown-1 자동 resolved.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#show",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11638,
  "max_ms": 11638,
  "sample_trace_id": "753922149806333051"
}

동일 구간의 대표 lock wait 로그 (Datadog):

{
  "timestamp": "2026-07-03 07:03:38 KST",
  "status": "info",
  "message": "[500] POST /api/v1/panos (Api::V1::PanosController#create)",
  "error": {
    "reason": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "code": "SYS50000",
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "Cupix::Errors::System"
  }
}

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

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (이 클러스터), 인시던트 전체로는 lock wait 60+ 건 + 지연된 read 3건
• 최초 발생: 2026-07-03 07:03 KST
• 최근 발생: 2026-07-03 07:03 KST

Root Cause Summary#

PanosController#show 자체는 단순한 PanoRepository#show(params[:id]) 호출로 read-only 트랜잭션이며 명시적 lock을 잡지 않는다. 그러나 동일 시각에 POST /api/v1/panos (PanoFactory#create!) 와 PUT /api/v1/jobs/:id/actions/postprocessor/complete 트랜잭션이 대량으로 실행되면서 pano/capture/record 관련 row들에 대해 Lock wait timeout exceeded 를 20초 넘게 반복 발생시켰다. InnoDB 는 read 쿼리라도 동일 row 를 변경 중인 쓰기 트랜잭션이 있으면 (repeatable-read 격리 하) SELECT ... FOR UPDATE 나 명시적 lock 없이도 metadata lock, secondary-index lock, 또는 gap lock 에 의해 대기할 수 있고, 특히 conflicting 트랜잭션이 innodb_lock_wait_timeout 근처(기본 50s 이나 서비스는 짧게 튜닝됨)까지 잡고 있으면 후행 read 도 함께 지연된다. 이 요청은 11.6s 를 대기한 후 정상 응답한 케이스로, 근본 원인은 show 코드가 아니라 동시 pano 생성/postprocessor 완료 트랜잭션의 lock hold 시간이 과도하게 길어져 발생한 InnoDB row-lock contention 이다.

Technical Analysis#

Code Path#

Entry point 는 표준 Rails 라우팅을 통한 PanosController#show 이다. set_pano before_action 은 show 를 예외로 두고 있어(except: %i[... show ...]), 요청은 곧바로 #show 액션에 진입한다.

before_action :set_pano, except: %i[index create bulk_update upload_candidates untrash purge show bulk mock nearest]

def show
  if params[:review_key].present?
    review_repository_instance = ReviewRepository.new(current_user: current_user)
    review = review_repository_instance.show(params[:review_key])

    @model = repository.new(current_user: current_user, review: review).show(params[:id])

    if !review_repository_instance._capture_ids.include?(@model.capture_id) || !review_repository_instance._level_ids.include?(@model.level_id)
      raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: 'Pano not found with review', review: { key: params[:review_key] }, pano: { id: params[:id] })
    end
  else
    @model = repository_instance.show(params[:id])
  end

  super
end

repository_instance.show(id) 는 BaseRepository#show → self.class.show 로 위임되어 결과적으로 Pano.find_by(id: ...) 계열 단순 SELECT 로 귀결된다. 명시적 트랜잭션이나 lock! 호출은 없다.

def show(id, visibility: Cyclable.visibility[:UNTRASHED], review_id: nil, capture_id: nil, skip_permission: false)
  _review_id = if review_id.present?
                 review_id
               elsif self.review.present?
                 self.review.id
               end

  @model = self.class.show(id, current_user: @current_user, visibility: visibility, review_id: _review_id, capture_id: capture_id, skip_permission: skip_permission)
end

Contention 을 만든 상대편은 pano 생성 경로다. PanosController#create 는 factory_instance.create!(params) 로 위임된다.

def create
  @model = factory_instance.create!(params)

  super
end

def create!(params = {})
  self.model = ::Pano.new

  if params[:capture_id].present?
    self.parent = CaptureRepository.new(current_user: self.current_user).show(params[:capture_id])
  elsif params[:capture].present?
    self.parent = CaptureRepository.new(current_user: self.current_user).show(params[:capture])
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'capture_id is required')
  end

  raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: "Can't create a pano") unless self.parent.pano_creatable?

  self.model.capture = self.parent
  self.model.record = self.parent.record

Postprocessor 완료 경로 (PUT /api/v1/jobs/:id/actions/postprocessor/complete) 도 같은 시각 다수 실패했으며, 이 컨트롤러는 ActiveRecord::LockWaitTimeout 를 502 응답으로 정직하게 반환한다 — 즉 create/postprocessor 트랜잭션이 pano/capture/record 계열 row 를 잡은 채로 lock timeout 까지 도달한다는 뜻이다.

기대 동작 vs 실제 동작: 기대는 단건 pano 조회가 수십 ms 안에 끝나는 것. 실제로는 동시에 진행 중이던 write 트랜잭션들이 pano/capture/record row 들에 lock 을 오래 걸어놓아, 이 read 트랜잭션이 11.6s 동안 lock 대기 후에야 진행되었다.

Log Evidence#

Datadog 쿼리 (재현용):

service:cupixworks-api "Slow query" OR "timeout" OR "Timeout"
time: 2026-07-02T21:55:00Z ~ 2026-07-02T22:15:00Z

service:cupixworks-api "Lock wait timeout"
time: 2026-07-02T21:55:00Z ~ 2026-07-02T22:15:00Z

Lock wait timeout 분포 (Lock wait timeout 텍스트 매칭, KST):

timestamp                    count
2026-07-03 07:03:15 KST      2
2026-07-03 07:03:17 KST      1
2026-07-03 07:03:19 KST      2
2026-07-03 07:03:21 KST      2
2026-07-03 07:03:23 KST      3
2026-07-03 07:03:25 KST      4
2026-07-03 07:03:27 KST      2
2026-07-03 07:03:30 KST      4
2026-07-03 07:03:32 KST      2
2026-07-03 07:03:34 KST      1
2026-07-03 07:03:37 KST      3
2026-07-03 07:03:38 KST      4
2026-07-03 07:03:48 KST      1
2026-07-03 07:04:02 KST      1
2026-07-03 07:04:20 KST      1

문제의 show 요청이 시작된 07:03:00 KST 직후부터 07:04:20 KST 까지 lock wait 실패가 60건 넘게 집중되며, 11.6s 지연 창(07:03:00–07:03:11 KST) 정확히 안에서 실패가 밀도 있게 나타난다.

같은 시각 다른 read 지연 (사이드보드가 하나의 인시던트로 묶은 세 클러스터):

e0e15b40-436b-4799-a616-6c51ef80e6f8  PointcloudsController#index          10021ms  06:57:45 KST
d94a3259-8473-4abc-9b14-96f68af4499e  PanosController#show                 11638ms  07:03:00 KST  (this)
cfc2776c-5d3d-4099-bba8-8d0348216461  TeamsController#invitation           45073ms  07:07:53 KST

세 read 가 자원(controller/모델) 종류는 다르지만 동일 API pod 그룹에서 같은 lock/DB 압박 창에 걸린 것으로 해석된다.

동시 warn 신호: 같은 창에서 Pano#_update_document "NotFound - attributes_in_database" warn 이 수십 건 발생 (Elasticsearch mirror 갱신 실패). 이는 write 트랜잭션이 커밋 전 검색 인덱스 반영을 시도했으나 DB 상태와 어긋난 정황을 시사한다. lock 자체의 원인은 아니지만 write 경로가 큰 부하 아래 있었다는 방증이다.

{
  "timestamp": "2026-07-03 07:09:57 KST",
  "status": "warn",
  "message": "NotFound - attributes_in_database",
  "class": "Pano",
  "function": "_update_document"
}

Trace 검색 실패: @trace_id:753922149806333051 로그 직검색은 0건이었다 (cupixworks-api 는 trace 를 APM 로만 보내고 log 에는 injection 되지 않는 것으로 확인). 따라서 span 단위 SQL breakdown 대신 시간 창 기반 상관관계로 확정했다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• APM span breakdown 확인: trace_id 753922149806333051 를 Datadog APM 에서 열어 (app/controllers/api/v1/panos_controller.rb:55-70 span 하위) 어떤 SQL/외부 호출이 11.6s 를 차지했는지 확정. 만약 특정 pano id / capture id 가 반복 등장하면 그 row 를 잡고 있던 write 트랜잭션이 대상. (RCA 자동화로는 접근 불가 — 사람이 UI 로 재확인 필요.)
• 원인 write 경로 락 검토: 같은 창에서 Cupix::Errors::System 500 을 낸 POST /api/v1/panos 처리 흐름 (app/controllers/api/v1/panos_controller.rb:43-47 → app/factories/pano_factory.rb:7- create!) 의 트랜잭션 스코프와 실행 시간을 조사. 특히 CaptureRepository#show, pano_creatable? 를 트랜잭션 안에서 호출하고 있는지 확인 — 만약 그렇다면 read-heavy pre-check 를 트랜잭션 밖으로 뺄 여지 있음.
• postprocessor complete 트랜잭션 검토: Api::V1::JobsController#complete_action 에서 pano/capture row 를 잡는 범위를 축소. 배치성 상태 업데이트가 있다면 chunking + 짧은 트랜잭션으로 분할.

단기 개선 (1주 이내)#

• innodb_lock_wait_timeout 및 트랜잭션 길이 계측: mysql.performance.innodb_row_lock_time (avg/max) 와 mysql.performance.innodb_row_lock_current_waits 를 Datadog dashboard 에 상시 노출. 값이 나오는지 (integration on) 부터 확인 — 이번 조사에서 관련 메트릭 쿼리가 빈 응답이었다.
• P99 latency 알람: Api::V1::PanosController#show (그리고 다른 자주 접근되는 read 리소스) 에 P99 > 3s 알람. 이번 케이스처럼 단일 발생이라도 catch 되도록.
• APM span 에 trace_id log injection: Rails logger tags 에 dd.trace_id 를 넣어, 다음 사고 시 @trace_id:... 로그 검색이 가능하게. (이번 사고 조사에서 이 조회가 0건이었던 것 참조.)

장기 개선 (재발 방지)#

• Pano/Capture write 경로 트랜잭션 최적화: PanoFactory#create! 및 postprocessor complete 트랜잭션에 대해 pessimistic lock 사용 여부, capture / record 갱신 순서, secondary-index 업데이트 빈도를 프로파일링해 lock hold 시간을 낮춘다.
• 읽기·쓰기 워크로드 분리 검토: 뷰어 read (show, index) 를 replica 로 라우팅하는 옵션 검토 (현재 all-primary 로 추정). Replica lag 허용치가 UX 상 문제없다면 read 를 primary lock storm 에서 격리.
• Idempotent / 배치화 postprocessor complete: 같은 시각 20+ 건의 postprocessor/complete 가 몰리면 pano 관련 인덱스가 lock 후보가 됨. 워커측에서 job 완료 콜백을 debounce / batch 로 정리.

Monitoring#

Release dashboard timeseries widget 용 쿼리 (모두 writing-datadog-monitoring-queries 규약 준수 — pipe/stats/threshold 미사용):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::panoscontroller#show}.as_rate()

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

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::panoscontroller#create}.as_rate()

sum:mysql.innodb.row_lock_waits{env:production}.as_rate()

avg:mysql.innodb.row_lock_time{env:production}

(MySQL 계열 메트릭이 대시보드에 값을 그리지 않는 경우 Datadog MySQL integration 활성화 상태부터 점검. 이번 RCA 중 mysql.performance.innodb_row_lock_waits 쿼리가 빈 결과였음 — needs verification.)

로그 감시용 (모니터에서 별도로 사용):

service:cupixworks-api "Lock wait timeout"

Risk Assessment#

• Risk level: medium — 단일 요청 지연 자체는 사용자 1명 영향이지만, 같은 창에서 pano 업로드 60+ 건 500/502 실패가 동반됐다. lock storm 이 재현되면 뷰어 UX 와 업로드 파이프라인이 동시에 흔들린다.
• 예상 복잡도: standard — 즉시 조치는 관측/설정, 근본 fix (트랜잭션 스코프 축소, read replica) 는 write 경로 리팩터를 요하며 회귀 리스크가 있다.