RCA: Api::V1::RecordsController#index latency spike (50.7 s)

Overview#

What Happened#

2026-06-27 04:22 KST 시각, production-us-west-2 환경의 cupixworks-api에서 GET /api/v1/records 한 건이 50745 ms 만에 200 OK로 응답했다. 같은 시각 같은 Puma host(ip-10-1-80-134.us-west-2)에서 Api::V1::PanosController의 여러 액션이 ActiveRecord::LockWaitTimeout 으로 약 50 s 이상 블로킹되며 502 응답을 반환하고 있었다. Records 요청 자체의 DB 측정 시간은 1805.93 ms로, 50 s 중 절대 다수는 ActiveRecord 외부의 대기 시간(MySQL connection 또는 Searchkick 호출 단계)에서 소비되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-27 04:06:25 KST — facility 8jc688의 Records 인덱스 한 건이 32249 ms 만에 200 응답 (선행 신호).
2. 2026-06-27 04:21:06 KST — Api::V1::PanosController 액션에서 ActiveRecord::LockWaitTimeout 502 응답이 us-west-2에서 시작.
3. 2026-06-27 04:22:47 KST — Cluster first_seen. Api::V1::RecordsController#index 요청이 50745 ms 후 200 응답. 같은 host의 Pano 요청들이 lock wait 으로 timeout 중.
4. 2026-06-27 04:24:00 KST — Pano lock wait timeout 마지막 발생 후 진정. 이후 동일 facility 의 Records 요청 5건은 700 - 800 ms 로 정상 응답.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::RecordsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 50745,
  "max_ms": 50745,
  "sample_trace_id": "4348598615794920273"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (latency-only cluster — 5xx 아님)
• 최초 발생: 2026-06-27 04:22:47 KST
• 최근 발생: 2026-06-27 04:22:47 KST
• 사용자 체감: cana 팀 사용자의 facility list 1페이지 로드가 50 s 동안 응답 없음 (UI freeze, refresh 유발 가능). 같은 시간대 us-west-2 의 wgyates 도메인 capture 업로드 (Pano 업로드 체크 endpoint) 가 502 로 실패.

Root Cause Summary#

us-west-2 production MySQL 인스턴스에서 Api::V1::PanosController 의 업로드 상태 확인 액션 (check_uploading, check_tile_uploading, mask_upload_url) 이 동일 row 또는 동일 인덱스에 대한 쓰기 lock 을 잡고 50 s 동안 풀지 않으면서 InnoDB lock wait timeout (50 s) 이 연쇄적으로 발생했다. 동일 Puma host (ip-10-1-80-134) 에서 처리되던 Api::V1::RecordsController#index 요청은 503/502 로 실패하지는 않았지만, 50 s 동안 MySQL connection 또는 read 단계에서 같은 lock 또는 connection-pool saturation 에 의해 대기했다. db 측정값 1805.93 ms 가 보여주듯 ActiveRecord 자체 SQL 실행 시간은 짧고, 50 s 의 대부분은 ActiveRecord 외부 대기 (connection acquire 또는 Searchkick → ActiveRecord 재조회 사이) 에서 누적된 것으로 추정된다. Records 요청 자체는 결국 200 으로 완료되었으므로 single-request bug 가 아니라 동시 발생한 Pano write-path lock 폭주의 부수 효과다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/records_controller.rb:11 (def index)
• Repository search: app/repositories/record_repository.rb:372 (_search)
• Elasticsearch 호출: app/repositories/record_repository.rb:477 (::Record.search(...))
• 결과를 ActiveRecord 로 재조회 + permission join: app/repositories/base_repository.rb:75-81 (permission_joins(default_joins(self.response.records), ...))
• 14 LEFT JOIN 권한 sub-query: app/repositories/record_repository.rb:143-354

def index
  record_query_option = Cupix::QueryOption::Record.new(get_query_option, params)
  records = repository_instance.search(record_query_option)

  render_api Renderable.new({
    search_result: records,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

if review.blank? && self.current_user.present?
  self.query_option.query[:bool][:must] += [
    {
      bool: {
        should: [
          { terms: { "facility.id": self.current_user.readable_facility_ids } },
          { terms: { id: self.current_user.directly_accessible_record_ids } }
        ]
      }
    }
  ]
end

response = ::Record.search(
  self.query_option.serializable_hash
).paginate(
  per_page: self.query_option.per_page,
  page: self.query_option.page
)

def search(query_option = nil)
  _search(query_option)

  begin
    if self.review.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review.id, skip_join: _skip_join?)
    elsif self.review_id.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review_id, skip_join: _skip_join?)
    elsif self.capture.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, capture_id: self.capture.id, skip_join: _skip_join?)
    else # = self.review_id.nil?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end

기대 동작: ES 검색 ~수십 ms + AR 재조회 ~수백 ms = 평소 0.7 - 2.5 s 응답 (동일 facility 의 다른 시각 측정치 723 ms / 739 ms / 2595 ms 와 일치).

실제 동작: 50.7 s 응답. db=1805.93 ms, view=0.09 ms, serialization=136 ms 합산이 1.94 s 에 불과하므로 약 48.8 s 가 측정되지 않는 대기 구간 (MySQL connection acquire, Searchkick HTTP 라운드트립, 또는 ActiveRecord 외부 mutex) 에서 소비되었다.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "Api::V1::RecordsController#index" @duration:>10000

Time range: 2026-06-26T19:00:00Z to 2026-06-26T20:00:00Z → 2 건만 hit.

문제의 요청 한 건의 raw 로그 (값만 발췌):

{
  "@timestamp": "2026-06-26T19:23:38.577Z",
  "duration": 50733.04,
  "db": 1805.93,
  "view": 0.09,
  "serialization": { "duration": 136 },
  "http": { "status_code": 200, "method": "GET", "url_details": { "path": "/api/v1/records" } },
  "controller": "Api::V1::RecordsController",
  "action": "index",
  "host": { "name": "ip-10-1-80-134.us-west-2.compute.internal" },
  "region": "us-west-2",
  "params": { "per_page": "100", "page": "1", "facility_key": "e8uxfx" },
  "team": { "domain": "cana", "id": 1165 },
  "request_id": "c7b76061-3db4-45b3-bfc7-3c1cd51bfaa3"
}

동일 시각 동일 host 의 Pano 요청 (대표 1건):

service:cupixworks-api region:us-west-2 "Lock wait timeout"

{
  "@timestamp": "2026-06-26T19:23:58.640Z",
  "duration": 53978.7,
  "error": {
    "class": "ActiveRecord::LockWaitTimeout",
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction"
  },
  "controller": "Api::V1::PanosController",
  "action": "check_tile_uploading",
  "http": { "status_code": 502 },
  "host": { "name": "ip-10-1-80-134.us-west-2.compute.internal" }
}

같은 1.5 시간 동안 us-west-2 에서 발생한 lock wait timeout 17 건. 모두 Api::V1::PanosController 의 check_uploading, check_tile_uploading, mask_upload_url 액션에서 발생. 19:21:06Z 부터 19:24:00Z 까지 집중.

같은 facility e8uxfx 의 정상 응답 비교 (1.5 시간 전, 같은 user/params):

duration=2595.35 ms, db=1271.68 ms, @timestamp=2026-06-26T18:44:58Z

→ 평소 2.6 s, 사고 시 50.7 s (~20 배 증가). DB 시간은 1.3 s → 1.8 s (소폭 증가)에 그치므로 SQL plan 회귀가 아니라 외부 대기.

Elasticsearch 측 에러 검색 결과 0 건:

service:cupixworks-api region:us-west-2 ("Elasticsearch" OR "search_phase_execution" OR "ConnectionFailed" OR "Net::ReadTimeout" OR "Faraday")

→ ES 자체의 timeout/에러 흔적은 없다.

Status board (incident 2026-06-26-svc-cupixworks-api--unknown-4, cupixworks-api service degraded) 가 같은 윈도우의 다른 3 cluster (37d67138, 9de1abf8, e2b8679d) 와 본 cluster (cfe24462) 를 묶고 있다 → 단일 cluster 가 아닌 서비스 전반 degradation 이라는 외부 증거.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 본 cluster 단독으로는 단발성 latency event (occurrence 1) 이며, root cause 는 Records 코드가 아닌 Pano write path 의 lock 폭주이므로 Api::V1::RecordsController#index 코드 변경 불필요.
• Pano lock 폭주를 별도 incident 로 추적해야 한다. 같은 service degradation incident 2026-06-26-svc-cupixworks-api--unknown-4 에 묶인 다른 cluster (37d67138-a043-4669-af16-3d0f6805fb46, 9de1abf8-94a7-4ee0-8812-1f217e973b99, e2b8679d-a3fb-4584-aac1-940a5cd51df7) 의 RCA 와 함께 보고 Pano cluster 가 있으면 그것을 우선 해결.
• 운영 측에서 사고 윈도우 (2026-06-26T19:21Z - 19:24Z) 에 us-west-2 RDS/Aurora cluster 의 innodb_row_lock_waits, innodb_row_lock_time, active_lock_holders 메트릭을 확인.

단기 개선 (1주 이내)#

• Api::V1::PanosController#check_uploading / check_tile_uploading / mask_upload_url 의 트랜잭션 범위를 축소하고 lock 보유 시간을 조사. 50 s 동안 row lock 을 잡는 정상 경로는 없을 가능성이 높으므로, long-running 업로드 polling 이 단일 트랜잭션 안에서 외부 호출 (S3, mask service 등) 을 기다리지 않는지 검증.
• Api::V1::RecordsController#index 의 _search 가 외부 대기 (Searchkick, MySQL connection acquire) 시간을 별도 metric 으로 노출하도록 instrumentation 추가. 현재 db=1805 ms 만 보이고 50 s 의 행방을 사후 추적하기 어렵다 → Searchkick 호출에 ActiveSupport::Notifications 구독 후 cupixworks.records.search.duration 같은 custom metric 발행.
• RecordRepository.permission_joins (app/repositories/record_repository.rb:143-354) 의 14 LEFT JOIN sub-query 가 본건의 원인은 아니지만 평상시에도 700 ms - 2.5 s 의 latency 를 만들고 있어 향후 lock 폭주 시 증폭 요인. EXPLAIN 으로 cost 와 index usage 점검 권장 (별도 ticket).

장기 개선 (재발 방지)#

• 업로드 상태 polling endpoint (check_uploading 등) 의 트랜잭션 / lock 모델 재설계: 가능하면 read-only 로 변경하거나 advisory lock 또는 Redis 기반 상태 머신으로 분리.
• Puma worker isolation: 한 host 의 lock-bound 요청이 다른 endpoint 의 read latency 를 50 s 까지 끌어올리는 구조는 worker pool 격리 (전용 endpoint group 또는 별도 process) 또는 connection pool 분리로 완화 가능.
• Service-level p99 latency SLO 정의 + lock wait timeout 발생 시 자동 dashboard / runbook 링크 → status-board 가 이미 묶고 있는 incident 와 통합.

Monitoring#

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

avg:trace.rack.request.duration.by.resource_service.95p{service:cupixworks-api,resource_name:api::v1::recordscontroller#index,env:production,region:us-west-2}

sum:mysql.innodb.row_lock_waits{env:production,region:us-west-2}.as_rate()

max:mysql.innodb.row_lock_time{env:production,region:us-west-2}

Datadog Log monitor:

service:cupixworks-api status:error "Lock wait timeout exceeded"

threshold: 5 분 윈도우에서 3 건 이상 → alert.

Risk Assessment#

• Risk level: medium (단발 200 응답이지만 동시 발생한 Pano 502 폭주는 사용자 영향 명확)
• 예상 복잡도: standard (Records 코드 자체는 변경 불필요. Pano lock 폭주 조사가 본 작업)