RCA: Api::V1::FacilitiesController#index slow trace (52s)

Overview#

What Happened#

2026-06-27 04:01 KST 에 cupixworks-api 의 Api::V1::FacilitiesController#index 요청 한 건이 52,435ms (52초) 만에 응답했다. 동시 윈도우(04:01 ~ 04:22 KST) 에 같은 서비스에서 SearchesController#counts(17초), RecordsController#index(51초) 지연 클러스터와 ReviewRepository#captures Elasticsearch 호출 타임아웃(10초)이 함께 발생했고, status-board 가 4건의 클러스터를 묶어 cupixworks-api service degraded 인시던트(2026-06-26-svc-cupixworks-api--unknown-4)로 등록했다. 직후 04:21 ~ 04:24 KST 에 panos 테이블에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 502 응답이 다수 발생, 같은 시간대에 API 평균 trace duration 이 평소 13초 대비 810초로 상승했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-27 04:01:37 KST — Api::V1::FacilitiesController#index 한 건이 52,435ms 로 완료 (이 클러스터의 first_seen)
2. 2026-06-27 04:14:08 KST — Api::V1::SearchesController#counts 16,984ms (cluster 9de1abf8)
3. 2026-06-27 04:17:26 ~ 04:17:28 KST — ReviewRepository#captures 에서 Failed to get captures - Operation timed out after 10001 milliseconds 2건 (cluster e2b8679d)
4. 2026-06-27 04:21:06 ~ 04:24:00 KST — panos 테이블에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 16건 (502 응답)
5. 2026-06-27 04:22:47 KST — Api::V1::RecordsController#index 50,745ms (cluster cfe24462)
6. 2026-06-27 04:26:20 ~ 04:26:26 KST — Pano, Group, Record 모델에서 NotFound - attributes_in_database warn 로그 다수 (인덱싱 콜백이 트랜잭션 롤백된 레코드를 참조)
7. status-board — 위 4 클러스터가 svc:cupixworks-api::unknown 스코프 인시던트 2026-06-26-svc-cupixworks-api--unknown-4 로 묶임 (open)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FacilitiesController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 52435,
  "max_ms": 52435,
  "sample_trace_id": "4514254013736018340"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (단, 같은 인시던트로 묶인 다른 3 클러스터 포함 시 총 4건의 cupixworks-api 지연/오류 이벤트)
• 최초 발생: 2026-06-27 04:01 KST
• 최근 발생: 2026-06-27 04:01 KST

Root Cause Summary#

Api::V1::FacilitiesController#index 한 건이 52초까지 늘어진 직접 원인은 같은 서비스 내부의 MySQL InnoDB lock contention 으로 판단된다. 같은 21분 윈도우 내에서 panos 테이블 쓰기 (check_uploading, check_tile_uploading, mask_upload_url) 가 연속적으로 Lock wait timeout exceeded 502 를 내고 있었고, 같은 시간대에 API 평균 trace duration 이 평소 13초에서 810초로 상승했다. FacilityRepository#search 의 결과 hydration 단계에서는 permission_joins 가 facilities, facility_permissions, workspace_permissions, team_permissions, grouped_users, reviews 등에 걸친 LEFT JOIN + GROUP BY id SQL 을 실행한다 (app/repositories/facility_repository.rb:299-444). 이 SQL 자체는 평소 빠르지만 DB 가 lock 으로 stall 한 상태에서는 단일 read 쿼리도 connection pool 대기 + InnoDB row lock 대기로 수십 초 누적될 수 있다. 따라서 이 cluster 는 단일 컨트롤러 버그가 아니라 DB-wide contention 의 외부 증상이며, status-board 가 이를 svc:cupixworks-api::unknown 인시던트로 묶은 것은 정확하다. lock 의 1차 원인(어느 쿼리가 long-held write lock 을 잡았는지)은 현재 Datadog 의 error/warn/info 로그만으로는 단정할 수 없으며 RDS slow query log 또는 InnoDB engine status 확인이 필요하다 — uncertain, needs verification.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/facilities_controller.rb:107
• Repository: app/repositories/facility_repository.rb:_search (ES) → app/repositories/base_repository.rb:search (SQL hydration)
• Failure point (latency hot spot, suspected): app/repositories/facility_repository.rb:299-444 (permission_joins SQL)

def index
  facilities = repository_instance.search(
    Cupix::QueryOption::Facility.new(get_query_option, params)
  )

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

search 는 BaseRepository#search 로 위임된다. 여기서 두 단계가 직렬로 일어난다 — (1) ES 쿼리, (2) ES 결과 ID 집합을 MySQL 에서 hydrate 하면서 권한 LEFT JOIN.

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), ...)
    elsif self.review_id.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), ...)
    elsif self.capture.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), ...)
    else
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), ...)
    end
  rescue Elasticsearch::Transport::Transport::Errors::BadRequest => e
    ...
  rescue Elasticsearch::Transport::Transport::ServerError => e
    raise unless e.message.start_with?('[429]')
    Cupix::Logger.error("Elasticsearch circuit breaker: #{e.message}", ...)
    raise Cupix::Errors::System.new(code: 'SYS20000', reason: 'Elasticsearch circuit breaker triggered (too many requests)')
  rescue StandardError => e
    Cupix::Logger.error(e.message.to_s, ...)
    raise Cupix::Errors::BadGateway.new(code: 'BG10002', reason: 'Bad Gateway error on Elasticsearch')
  end
  ...
end

ES 단계는 같은 시간대 다른 cluster (e2b8679d) 에서 10초 후 Faraday 타임아웃을 던진 바 있다. 하지만 본 cluster 는 ES 에서 raise 하지 않고 52초까지 완주했으므로, ES 응답은 받았고 그 뒤 SQL hydration 단계에서 추가로 stall 했을 가능성이 있다. permission_joins 의 SQL 모양은 다음과 같다.

record.joins("
  LEFT JOIN (...) AS review_public_permissions ...
  LEFT JOIN (...) AS facility_user_permissions ...
  LEFT JOIN (...) AS facility_group_permissions ...
  LEFT JOIN (...) AS facility_system_group_permissions ...
  LEFT JOIN (...) AS workspace_user_permissions ...
  LEFT JOIN (...) AS workspace_group_permissions ...
  LEFT JOIN (...) AS team_user_permissions ...
  LEFT JOIN (...) AS team_group_permissions ...
  LEFT JOIN (...) AS team_system_group_permissions ...
").group('id').select(_select).where("...")

facility_permissions, workspace_permissions, team_permissions, grouped_users 에 대한 다중 LEFT JOIN 과 GROUP BY id 가 포함되어 있다. DB 가 lock contention 상태이면 이 read 쿼리도 row-level lock 또는 metadata lock 대기에 걸려 누적 지연이 수십 초로 커질 수 있다.

기대 동작 vs 실제 동작:

• 기대: _search 50300ms (ES) + permission_joins 50500ms ≈ 1초 이내 응답
• 실제: 52,435ms — 평소의 50~100배

Log Evidence#

같은 21분 윈도우의 동시 발생 패턴이 본 cluster 가 단일 컨트롤러 문제가 아니라 인프라 레벨 contention 임을 보여준다.

Datadog 쿼리 (status-board 가 묶은 다른 클러스터의 에러 로그):

service:cupixworks-api status:error

{
  "timestamp": "2026-06-26T19:17:28.401Z",
  "status": "error",
  "message": "Failed to get captures - Operation timed out after 10001 milliseconds with 0 bytes received",
  "class": "ReviewRepository",
  "function": "captures"
}
{
  "timestamp": "2026-06-26T19:17:26.735Z",
  "status": "error",
  "message": "Failed to get captures - Operation timed out after 10001 milliseconds with 0 bytes received",
  "class": "ReviewRepository",
  "function": "captures"
}

Datadog 쿼리 (MySQL lock wait timeout 폭증):

service:cupixworks-api "Lock wait timeout"

쿼리 결과 16건 — 04:21:06 ~ 04:24:00 KST 사이에 panos 테이블 4개 엔드포인트에서 반복:

{
  "timestamp": "2026-06-26T19:24:00.646Z",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/90301440/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-26T19:21:06.022Z",
  "status": "info",
  "message": "[502] POST /api/v1/panos/90315542/mask_upload_url (Api::V1::PanosController#mask_upload_url)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

Datadog 쿼리 (인덱싱 콜백 실패 — 트랜잭션 롤백된 row 를 ES 에 반영하려다 fail):

service:cupixworks-api status:warn

{
  "timestamp": "2026-06-26T19:26:22.321Z",
  "status": "warn",
  "message": "NotFound - attributes_in_database",
  "class": "Pano",
  "function": "_update_document"
}
{
  "timestamp": "2026-06-26T19:26:25.519Z",
  "status": "warn",
  "message": "NotFound - attributes_in_database",
  "class": "Group",
  "function": "_update_document"
}

Datadog 쿼리 (API 전체 평균 응답 시간):

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

윈도우 마지막 30분 평균이 6.9 → 10.0 → 8.8 → 3.5 초로 평소 13초 대비 35배 상승 (위 두 cluster latency 와 정합).

status-board 결과 (clip):

{
  "scope": "svc:cupixworks-api::unknown",
  "active": {
    "id": "2026-06-26-svc-cupixworks-api--unknown-4",
    "title": "cupixworks-api service degraded",
    "status": "open",
    "started_at": "2026-06-26T19:01:37.996Z",
    "last_event_at": "2026-06-26T19:22:47.494Z",
    "cluster_ids": [
      "37d67138-a043-4669-af16-3d0f6805fb46",
      "9de1abf8-94a7-4ee0-8812-1f217e973b99",
      "e2b8679d-a3fb-4584-aac1-940a5cd51df7",
      "cfe24462-0164-4097-acea-c69855c91566"
    ]
  }
}

또한 status-board recent 에 따르면 같은 svc:cupixworks-api::unknown 스코프 인시던트가 2026-06-26 하루에만 3번 (01:25, 11:22, 15:27) 더 발생해 본 사건과 동일 패턴의 재발성이 의심된다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• RDS InnoDB 진단: 04:01 ~ 04:24 KST 시간대에 대해 RDS Performance Insights / SHOW ENGINE INNODB STATUS / slow query log 를 확보하여 panos 테이블에서 long-held write lock 을 잡은 트랜잭션을 식별. 후보 — panos.check_uploading, panos.check_tile_uploading, panos.mask_upload_url 의 update 트랜잭션이 외부 S3 호출 등으로 길어졌을 가능성. 코드 위치: app/controllers/api/v1/panos_controller.rb.
• 이 cluster 자체에 대한 코드 수정은 불필요 (외부 증상). RDS 진단 결과에 따라 panos 업데이트 트랜잭션 범위 축소가 후속 fix 가 될 수 있다.

단기 개선 (1주 이내)#

• Pano upload 콜백의 트랜잭션 범위 축소: panos_controller.rb 의 check_uploading / check_tile_uploading / mask_upload_url 가 외부 I/O (S3 head/check) 를 DB transaction 안에서 호출하는지 확인하고, 외부 호출은 트랜잭션 밖으로 분리. 트랜잭션 시간이 줄어들면 lock 보유 시간이 줄어 다른 read 쿼리 대기가 사라진다.
• ES + SQL hydration 직렬화 비용 축소: BaseRepository#search (base_repository.rb:70) 의 permission_joins 결과를 페이지 단위로 limit (예: per_page 적용 후 권한 조인) 하도록 검토. 현재는 ES 결과 전체에 대해 JOIN+GROUP BY 한 다음 paginate 가 동작하는지 코드 추가 검증 필요.
• read timeout / circuit breaker: 컨트롤러 레벨 또는 Rack middleware 에서 단일 요청 처리 시간을 30초로 클램프하여 50초+ 요청이 worker 점유로 전체 처리량을 깎는 cascade 를 방지.

장기 개선 (재발 방지)#

• Permission denormalization: permission_joins 의 9개 LEFT JOIN 구조 자체를 효과 있는 컬럼/머티리얼라이즈드 뷰로 단순화 (장기 과제). 동일 SQL 이 모든 list 엔드포인트에서 호출되므로 ROI 가 큼.
• slow trace alert: 단일 클러스터가 trigger 되기 전에 같은 서비스에서 avg:trace.rack.request.duration > 5s 가 5분 지속되면 자동 알람 (status-board recent 에 따르면 같은 인시던트가 하루 4회 재발 — 감지가 늦음).

Monitoring#

writing-datadog-monitoring-queries 가이드를 따라 release dashboard timeseries widget 에 그대로 들어갈 수 있는 형태로 작성:

평균/95p 응답 시간 (전체 cupixworks-api):

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

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

FacilitiesController#index resource 단위 지연:

avg:trace.rack.request.duration.by_resource_service{service:cupixworks-api,resource_name:api::v1::facilitiescontroller#index,env:production}

MySQL lock wait timeout 발생률 (logs facet count):

logs("service:cupixworks-api \"Lock wait timeout\"").index("*").rollup("count").by("resource_name")

Elasticsearch 호출 실패율:

logs("service:cupixworks-api \"Failed to get captures\"").index("*").rollup("count")

API 호스트 CPU/메모리 (인스턴스 과부하 confound 배제):

avg:system.cpu.user{service:cupixworks-api}

avg:system.mem.used{service:cupixworks-api}

Risk Assessment#

• Risk level: medium-high — 단일 cluster 는 1회 발생이지만 같은 svc:cupixworks-api::unknown 스코프 인시던트가 2026-06-26 하루에만 4회, 2026-06-24 에 2회 재발하고 있어 운영 영향이 누적 중. 사용자 영향은 page load 50초 → 클라이언트 retry/포기 가능성.
• 예상 복잡도: standard — 코드 수정 자체는 작음 (트랜잭션 범위 축소). 단, 원인 식별을 위한 RDS 진단 + DBA 협의가 선행되어야 함.