RCA: Api::V1::Admin::CapturesController#index 519s latency

Overview#

What Happened#

2026-06-26 10:42 KST에 cupixworks-api 서비스의 admin 엔드포인트 Api::V1::Admin::CapturesController#index 요청 한 건이 약 519초(8분 39초) 동안 실행됐다. 단일 trace(2099774284021346103)에서 발생했고 region은 ap-southeast-2, tenant는 cupix다. 동일 시간대에 panos 테이블을 대상으로 한 광범위한 InnoDB row-lock 경합이 진행 중이었고, status board는 본 cluster를 2026-06-26-svc-cupixworks-api--unknown-1 인시던트(같은 service에서 30분 윈도우 내 7개 latency cluster 묶음)에 포함시켰다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-26 10:25 KST — svc:cupixworks-api::unknown parent incident 시작 (Api::V1::PanosController#update 41.5s latency, cluster 943fdcb4).
2. 2026-06-26 10:33:53 KST (추정) — 본 cluster 대상 요청 시작 (last_seen 10:42:32 KST − 519s).
3. 2026-06-26 10:42:32 KST — 본 trace last_seen. APM 기준 trace 종료 시각.
4. 2026-06-26 10:45:51 KST 이후 — panos 테이블 대상 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 502 응답 다수 발생 (Datadog 로그 19건 확인). duration ≈ 50,000ms = MySQL innodb_lock_wait_timeout 기본값.
5. 2026-06-26 10:53:30 KST — Parent incident 해소 (status board resolved_at).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::Admin::CapturesController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 519016,
  "max_ms": 519016,
  "sample_trace_id": "2099774284021346103"
}

본 cluster는 latency cluster이며 exception/스택 트레이스가 없다. Datadog 로그에서 Admin::CapturesController#index의 5xx/error 항목은 발견되지 않았다(쿼리 service:cupixworks-api ("CapturesController#index" OR "Admin::CapturesController") (502 OR 500 OR 504) — 0건).

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-26 10:42 KST
• 최근 발생: 2026-06-26 10:42 KST
• 사용자 영향: 단일 trace이지만 519초 동안 단일 Puma worker가 점유됨. 동시간대 parent incident에 묶인 다른 6개 cluster와 함께 cupixworks-api 전체의 응답 지연/실패 풀을 키우는 데 기여했다.

Root Cause Summary#

Api::V1::Admin::CapturesController#index는 Admin::CaptureRepository#search → _search(Elasticsearch ::Capture.search) → permission_joins (MySQL captures 테이블 위 16개 LEFT JOIN 서브쿼리, GROUP BY id) 순서로 동작한다. 코드 자체에 결정적 결함은 없지만 ES 응답을 받은 후 permission_joins로 MySQL에 매우 무거운 권한 집계 쿼리를 던지는 구조다. 사건 시각 ap-southeast-2 / tenant cupix의 production DB에서는 panos 테이블 중심의 광범위한 InnoDB row-lock 경합이 진행 중이었고(Mysql2::Error::TimeoutError: Lock wait timeout exceeded 502 다수 — 10:45 KST 이후), 같은 DB 인스턴스와 connection pool을 공유하는 본 요청의 permission_joins SQL이 connection 획득 또는 buffer-pool/lock 경합으로 인해 정상보다 수십·수백 배 지연됐다. 519초 = 10× innodb_lock_wait_timeout(50s) 수준이며, 한 단일 쿼리의 lock wait가 아니라 controller 진입 이후 여러 단계(인증, ES 쿼리, permission_joins, serialization)가 연쇄적으로 지연되어 누적된 결과로 본다. 본 cluster는 단독 root cause가 아니라 parent incident (2026-06-26-svc-cupixworks-api--unknown-1)의 부수 피해다. 정확히 어느 단계에서 얼마나 지연됐는지는 APM span 트리 없이 로그만으로 단정하기 어렵다 — uncertain -- needs verification.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/admin/captures_controller.rb:10
• Repository search: app/repositories/admin/capture_repository.rb:63 (_search)
• Elasticsearch query: app/repositories/admin/capture_repository.rb:166-171
• Permission join (heavy SQL): app/repositories/capture_repository.rb:279-505 (permission_joins)
• Wrap in search: app/repositories/base_repository.rb:70-112

controller는 ES 검색 결과를 받아 MySQL에서 권한 집계를 다시 수행한다:

def index
  captures = repository.new(current_user: current_user).search(
    Cupix::QueryOption::Capture.new(get_query_option(enable_current_team: false), params)
  )

  render_api Renderable.new(
    search_result: captures,
    is_collection: true,
    serializer_option: @serializer_option.merge(params: { current_user: current_user })
  )
end

_search는 Elasticsearch에 페이지네이션된 쿼리를 던진다:

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

이후 BaseRepository#search가 ES 결과를 MySQL captures 테이블에 다시 매핑하면서 default_joins + permission_joins를 적용한다:

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
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end

default_joins는 captures에 7개 association을 inner join한 뒤 20여 컬럼을 select한다:

def self.default_joins(record)
  record.includes(:reviewers, :storage).joins(:level, :record, :capture_type, :facility, :workspace, :team, :user).select('
    captures.*,
    records.note AS record_note,
    ...
    capture_types.migrated_from AS capture_type_migrated_from
  ')
end

permission_joins는 16개의 derived-table LEFT JOIN(review/capture/record/facility/workspace/team × user/group/system_group/public)을 붙이고 GROUP BY id로 집계한다:

record.joins("
  LEFT JOIN ( SELECT reviews.id AS review_id, 2 AS permission ... ) AS review_public_permissions
  LEFT JOIN ( SELECT review_id, permission FROM review_permissions ... ) AS review_user_permissions
  ...
  LEFT JOIN ( SELECT team_id, permission ... ) AS team_system_group_permissions
    ON team_system_group_permissions.team_id IS NULL
").group('id').select(_select).where("
  (
    GREATEST(IFNULL(facility_user_permissions.permission, 0),
             IFNULL(facility_group_permissions.permission, 0)) = 1
    AND GREATEST(IFNULL(record_user_permissions.permission, 0), ...) > 0
  )
  OR ...
")

기대 동작은 정상 부하에서 수백 ms~수 초 안에 끝나는 합성 쿼리. 실제 동작은 본 trace에서 519초 — DB 경합으로 인해 connection 획득 또는 SQL 실행이 비정상적으로 지연됐다.

Log Evidence#

핵심 쿼리 1 — 본 endpoint 5xx 여부 확인:

service:cupixworks-api ("CapturesController#index" OR "Admin::CapturesController") (502 OR 500 OR 504)
범위: 2026-06-26T00:30:00Z..2026-06-26T02:30:00Z
결과: Found 0 logs

→ 본 endpoint가 5xx로 끝나지는 않았다. 200 OK로 응답했지만 519s 소요. trace_id(2099774284021346103) 직접 검색으로는 Rails request 로그를 찾지 못했다 (service:cupixworks-api 2099774284021346103 — 0건). request 로그에 trace_id 태깅이 누락된 케이스로 보인다 — uncertain -- needs verification.

핵심 쿼리 2 — 동일 시간대 동일 DB의 panos lock contention:

service:cupixworks-api ("Lock wait timeout" OR "LockWaitTimeout" OR "Mysql2::Error::TimeoutError")
범위: 2026-06-26T01:25:00Z..2026-06-26T02:00:00Z
결과: Found 19 logs

대표 로그:

{
  "timestamp": "2026-06-26 10:45:51 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/14132644/check_tile_uploading (Api::V1::PanosController#check_tile_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

{
  "timestamp": "2026-06-26 10:53:29 KST",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/14133757/check_mask_uploading (Api::V1::PanosController#check_mask_uploading)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

본 cluster의 trace 종료 시각(10:42:32 KST)은 첫 lock-wait-timeout 발생(10:45:51 KST)보다 약 3분 빠르지만, parent incident 시작(10:25 KST)과 cluster 시작 추정 시각(10:33:53 KST)을 함께 보면 본 요청은 DB 경합이 이미 누적되기 시작한 윈도우 안에서 실행됐다. 동일 윈도우의 peer cluster d22ba254-b364-411b-801f-af7799b40331 (Assets#download 92.9s) RCA도 같은 lock-contention을 root cause로 식별했다.

핵심 쿼리 3 — Elasticsearch 회로 차단/오류 여부 확인:

service:cupixworks-api (Elasticsearch OR "circuit breaker" OR "BadGateway" OR "SYS20000" OR "BG10002")
범위: 2026-06-26T01:25:00Z..2026-06-26T02:00:00Z
결과: Found 0 logs

→ ES 측 회로 차단/오류는 없었다. 지연은 DB 경로에서 발생했다고 보는 게 합리적.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• Parent incident 2026-06-26-svc-cupixworks-api--unknown-1의 root-cause RCA(peer cluster d22ba254, fa2be8d1, 48253066)를 따라간다. 본 cluster 자체는 부수 피해이므로 단독 코드 수정 대상이 아니다.
• panos 테이블 lock contention 원인 트랜잭션을 찾는다 — Api::V1::PanosController#check_tile_uploading / check_mask_uploading / mask_upload_url이 502를 다수 던졌다. 해당 액션이 잡는 row-level lock의 범위/지속시간을 점검하고, UPDATE 트랜잭션을 짧게 분리하는 방향을 검토한다 — uncertain -- needs verification (panos 코드 별도 확인 필요).

단기 개선 (1주 이내)#

• Admin::CaptureRepository#search에 statement timeout을 명시한다 — 현재 519s 동안 단일 Puma worker가 점유되어 capacity가 줄어드는 cascading failure 패턴을 차단한다. Rails의 ActiveRecord::Base.connection.execute("SET SESSION MAX_EXECUTION_TIME=30000") 또는 controller-level deadline middleware 도입을 검토한다. (app/repositories/base_repository.rb:70, app/controllers/api/v1/admin/captures_controller.rb:10)
• permission_joins의 16개 LEFT JOIN derived table 쿼리(app/repositories/capture_repository.rb:322-471)에 대해 평소 부하에서의 쿼리 실행 계획/시간을 측정하고, GROUP BY id와 MAX() 집계가 인덱스를 잘 활용하는지 검증한다. 이상치(p99) 시간을 측정해 두면 광역 DB 경합 시 본 endpoint가 얼마나 더 취약해지는지 정량화할 수 있다 — uncertain -- needs verification.

장기 개선 (재발 방지)#

• 권한 집계는 모든 ES 검색 후 항상 재실행된다 — 캡처 리스트 응답 모델에 자주 호출되는 권한 정보를 ES 인덱스에 비정규화하여 store하고 권한 join을 생략하거나 가벼운 in-memory filter로 대체하는 구조 변경을 검토한다.
• 광역 DB 경합 발생 시 영향 받는 모든 API를 한 번에 보는 SLO/대시보드(예: cupixworks-api p95/p99 latency by resource_name)와 자동 페일오버(read replica routing 또는 admin 트래픽 격리) 정책을 검토한다.

Monitoring#

다음 Datadog 쿼리를 release dashboard에 timeseries widget으로 추가한다 (writing-datadog-monitoring-queries 가이드 준수 — | stats, count by(...) 같은 monitor-only 문법 금지).

본 endpoint의 응답 시간 p95:

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::admin::capturescontroller#index}

본 endpoint의 분당 호출 수:

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

cupixworks-api 전체 p95 (광역 degradation 조기 감지):

p95:trace.rack.request.duration{service:cupixworks-api,env:production}

panos 테이블 lock-wait-timeout 비율(parent incident 조기 감지):

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

알림 임계치 예시:

• 본 endpoint p95 > 5s 5분 지속 → warn
• 본 endpoint p95 > 30s 5분 지속 → page (519s급 trace가 또 나오면 사용자 영향이 크다)
• panos 502 rate > 0.1/s 5분 지속 → page (parent incident 조기 감지)

Risk Assessment#

• Risk level: medium — 본 cluster 단독은 1 trace, low severity이지만 같은 root cause(panos 테이블 lock 경합)가 같은 시간대에 7 cluster를 만들어낼 만큼 광역 영향을 끼쳤다. 동일 패턴이 재발하면 단일 admin 요청이 8분 이상 묶일 수 있어 사용자 경험과 worker capacity 양쪽에 압박.
• 예상 복잡도: critical — root cause는 본 cluster의 controller가 아니라 별도 도메인(panos write path)에 있다. 본 cluster에서 가능한 짧은 fix는 statement timeout 추가뿐이며, 근본 해결은 parent incident root-cause를 따라가야 한다.