RCA: Api::V1::RecordsController#show latency (226s)

Overview#

What Happened#

2026-07-01 11:15 KST 경 cupixworks-api의 Api::V1::RecordsController#show 요청 1건이 226.6초(226,589ms) 동안 지속되었다. 같은 시간대에 records, panos, captures, editings, jobs 관련 쓰기 API에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 502 에러가 45건 이상 발생했으며, 이 latency 스파이크는 그 InnoDB 락 경합 이벤트 tail에 걸린 read 요청이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 10:33 KST — svc:cupixworks-api::unknown 관련 클러스터 첫 발생 (incident 2026-07-01-svc-cupixworks-api--unknown-1).
2. 2026-07-01 10:51 KST — 첫 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 발생 (JobsController#update).
3. 2026-07-01 10:53–10:55 KST — Pano/Capture 쓰기 API에서 lock wait timeout이 대량으로 발생 (분당 5–7건).
4. 2026-07-01 11:02 KST — 상기 svc-level 인시던트 자동 해소 처리 (resolved_at).
5. 2026-07-01 11:11:31 KST — 문제의 RecordsController#show 요청 시작 (추정: last_seen - 226.6s).
6. 2026-07-01 11:15:18 KST — 요청 226.6s 만에 종료 → 본 클러스터 감지.
7. 2026-07-01 11:19 KST — 마지막 lock wait timeout (EditingsController#update). 이후 관련 502 로그 관찰되지 않음.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::RecordsController#show",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 226589,
  "max_ms": 226589,
  "sample_trace_id": "3219083934536030476"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (>500ms slow-trace 기준)
• 최초 발생: 2026-07-01 11:15 KST
• 최근 발생: 2026-07-01 11:15 KST
• 연관 502: 45+건 (lock wait timeout)

Root Cause Summary#

2026-07-01 10:51–11:19 KST 사이 MySQL 상에서 records/panos/captures/editings 계열 테이블에 대한 InnoDB 행/gap 락 경합이 지속되었다. 다수의 write API(PanosController#check_uploading, check_tile_uploading, stitched, check_mask_uploading, CapturesController#update_meta_by_key, EditingsController#update, JobsController#update) 가 트랜잭션 안에서 같은 record 계열 row들을 lock한 상태로 오래 유지되었고, RecordsController#show 는 BaseRepository.show 에서 permission_joins(default_joins(...)) — 즉 records/facilities/workspaces/teams 다중 JOIN + 14개의 permission LEFT JOIN — 쿼리를 실행하기 때문에 같은 row에 대한 read snapshot을 확보할 때 lock 대기에 걸렸다. 결과적으로 read 요청 1건이 innodb_lock_wait_timeout 근처(~50s)를 여러 번 대기하며 226.6초의 wall-clock latency로 관측되었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/records_controller.rb:9 — before_action :set_record
• set_record가 매 요청마다 repository 조회 수행: app/controllers/api/v1/records_controller.rb:63-65
• 실제 조회는 BaseRepository.show 안에서 permission_joins + default_joins로 넘어감: app/repositories/base_repository.rb:306-343
• 조인 정의: app/repositories/record_repository.rb:131-355
• Failure point: app/repositories/record_repository.rb:143-354 — 광범위한 permission JOIN 쿼리가 락 대기에 걸림.

Controller의 before_action은 write API가 아닌 read API(show)에서도 무조건 수행된다:

before_action :set_record, except: %i[create index untrash purge mock bulk_share bulk_unshare]

# ...

protected

def set_record
  @model = repository_instance.show(params[:id])
end

BaseRepository#show는 요청 특성(read/write) 구분 없이 매번 permission JOIN을 다시 계산한다:

def self.show(key_or_id_or_model, current_user: nil, visibility: Cyclable.visibility[:UNTRASHED], review_id: nil, capture_id: nil, skip_permission: false)
  # ...
  query =
    if skip_permission || current_user == ::User.unauthorized_user
      where(attrs)
    elsif current_class == ::Review || (review_id || capture_id).present?
      permission_joins(default_joins(current_class), current_user, review_id: review_id || -1, capture_id: capture_id || -1).where(attrs)
    elsif current_user.present?
      permission_joins(default_joins(current_class), current_user).where(attrs)
    else
      raise Cupix::Errors::System.new(code: 'SYS30000', reason: 'current_user or review is required on Repository')
    end

  scope = current_class.visibility_scope(visibility)
  model = query.merge(scope).first

RecordRepository.permission_joins가 실제 발행하는 JOIN — records 자체 조인 + 14개의 permission subquery LEFT JOIN — 이 lock 경합 대상 테이블(records, facility_permissions, record_permissions, ...) 을 동시에 스캔한다:

def self.default_joins(record)
  record.includes(:storage).joins(:facility, :workspace, :team).select("
    records.*,
    workspaces.name AS workspace_name,
    facilities.name AS facility_name,
    facilities.key AS facility_key,
    teams.qa_preference AS team_qa_preference,
    facilities.qa_preference AS facility_qa_preference,
    facilities.cycle_state AS applied_cycle_state
  ")
end

동일 시간대에 write API 쪽은 트랜잭션 안에서 records/panos/captures row를 lock 상태로 잡고 있어 위 read 쿼리가 스냅샷 획득에 걸리는 시간이 크게 늘어난다.

기대 동작 vs 실제 동작:

• 기대: 단순 record 상세 조회는 100ms 이내 응답.
• 실제: MySQL row lock 대기 → 요청 226.6초 유지.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "Lock wait timeout"
2026-07-01T01:30:00Z → 2026-07-01T02:30:00Z

45건의 502 응답 중 대표 항목:

{
  "timestamp": "2026-07-01 11:19:21 KST",
  "status": "info",
  "message": "[502] PATCH /api/v1/editings/1201005 (Api::V1::EditingsController#update)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-07-01 11:18:11 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/90887557/check_uploading (Api::V1::PanosController#check_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-07-01 10:53:16 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/captures/724756/meta/prop (Api::V1::CapturesController#update_meta_by_key)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

같은 시간대에 Api::V1::RecordsController#show는 정상 응답(200)을 계속 반환하고 있었다 (아래 예):

2026-07-01 11:15:52 KST  info  [200] GET /api/v1/records/18327 (Api::V1::RecordsController#show)
2026-07-01 11:15:42 KST  info  [200] GET /api/v1/records/18327 (Api::V1::RecordsController#show)
2026-07-01 11:15:13 KST  info  [200] GET /api/v1/records/134695 (Api::V1::RecordsController#show)
2026-07-01 11:15:08 KST  info  [200] GET /api/v1/records/134715 (Api::V1::RecordsController#show)

즉 대부분의 show 요청은 정상 처리되었고, 특정 record row가 write 트랜잭션과 겹친 1건만 226.6초 지연을 겪었다. sample_trace_id: 3219083934536030476 은 로그 인덱스에서 검색되지 않았다(APM 트레이스에만 존재) — 다음 쿼리는 결과 0:

@trace_id:3219083934536030476
2026-07-01T02:00:00Z → 2026-07-01T02:20:00Z

Status board 컨텍스트: 같은 서비스에서 2026-07-01-svc-cupixworks-api--unknown-1 (10:43–11:02 KST) 인시던트가 방금 resolved 처리되었고, 본 slow trace는 그 tail에 발생했다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 실제 lock을 잡고 있는 write 경로 파악이 우선. 다음 파일에서 트랜잭션 범위를 검토하고 트랜잭션 내부에서 수행되는 원격 호출/무거운 검증을 트랜잭션 밖으로 분리:
  • app/controllers/api/v1/panos_controller.rb의 check_uploading, check_tile_uploading, stitched, check_mask_uploading 액션
  • app/controllers/api/v1/captures_controller.rb의 update_meta_by_key
  • app/controllers/api/v1/editings_controller.rb의 update 이들이 동일 tenant/facility의 record row를 SELECT ... FOR UPDATE / autoincrement lock / gap lock 형태로 오래 잡고 있을 개연성이 높다.
• read-only 조회 경로에서는 락 대기 시간을 짧게 두어 실패를 빠르게 감지하도록 SELECT에 SET LOCAL innodb_lock_wait_timeout = ? 을 적용하는 방향 검토. 현재 BaseRepository#show는 무제한적으로 대기한다.

단기 개선 (1주 이내)#

• BaseRepository#show의 permission_joins(default_joins(...)) 쿼리를 read replica로 라우팅. Rails 6+ connected_to(role: :reading) 활용. read 쿼리가 write 트랜잭션과 같은 primary 커넥션에서 락 대기하는 구조를 근본적으로 회피할 수 있다.
• Slow trace를 자동 알람: 본 클러스터가 감지된 threshold(>500ms)는 너무 관대. Records show의 p99 baseline이 수백 ms 이하이므로 alerts는 5s/10s 수준으로 잡는다.
• RecordsController#show에 request timeout(예: rack-timeout 30s)을 걸어 클라이언트 dangling을 방지.

장기 개선 (재발 방지)#

• Pano/Capture 상태 갱신을 큰 트랜잭션에서 분리. check_uploading, stitched, check_tile_uploading 는 상태 전이 검증 + records/captures counter cache 업데이트를 하나의 트랜잭션에서 수행하는 것으로 추정되며, 이를 (1) 상태 전이 커밋과 (2) counter cache 갱신을 순서를 나누어 짧은 트랜잭션 여러 개로 분리.
• InnoDB deadlock/lock-wait 관측성: SHOW ENGINE INNODB STATUS 스냅샷을 lock 폭주 시점에 자동으로 수집하는 sidecar(예: mysqld-exporter + custom job) 도입.
• Read 경로 전면 read replica 라우팅 (ApplicationRecord.connected_to(role: :reading) do ... end) — 특히 dashboard/list/show 계열.

Monitoring#

APM slow-trace 카운트 (본 클러스터 임계):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::recordscontroller#show,env:production} by {resource_name}.as_count()

MySQL InnoDB row lock 대기시간(초):

avg:mysql.innodb.row_lock_time{*}.as_rate()

MySQL 슬로우 쿼리 비율:

avg:mysql.performance.slow_queries{*}.as_rate()

Lock wait timeout 발생 카운트 (Datadog Log-based metric으로 사전 생성 필요; 아래는 raw log query 재현용):

service:cupixworks-api "Lock wait timeout exceeded"

Risk Assessment#

• Risk level: medium — 사용자 1명이 226초 대기 후 응답을 받은 것이고, 동시간대 45건의 502가 upload/edit 흐름을 차단했다. 재현 조건(write 락 폭주)이 다시 오면 read 쪽도 다시 스톨된다.
• 예상 복잡도: standard — write 트랜잭션 범위 축소는 controller/service별 리팩토링이 필요하지만 인터페이스 변경은 없다. Read replica 도입은 인프라 변경 병행 필요(critical 아님).