RCA: Api::V1::LevelsController#index latency (18627 ms)

Overview#

What Happened#

2026-07-03 16:33 KST에 cupixworks-api의 Api::V1::LevelsController#index 요청 한 건이 18627 ms 동안 실행되어 latency cluster로 감지되었다. 해당 요청은 HTTP 200으로 응답에 성공했지만 DB에서 7204 ms, serialization에서 1661 ms를 소비했다. 동일 시간대에 다른 controller들도 광범위하게 DB 지연을 겪고 있어 개별 endpoint 결함이 아닌 fleet-wide DB 지연 사건의 한 표본이다.

Quick Facts#

Affected Teams#

같은 시간대(07:33-07:44 UTC)에 weoneil, ellisdon, accoes 등 다른 tenant들도 DB > 3 s 요청을 다수 관측했다. cluster 스코프는 표본 1건이지만 실제 사용자 impact는 다중 tenant에 걸쳐 있다.

Timeline#

1. 2026-07-03 16:33:13 KST — 요청 시작 (finish - duration으로 역산)
2. 2026-07-03 16:33:32 KST — 요청 종료, HTTP 200 (@timestamp: 2026-07-03T07:33:32.095Z)
3. 2026-07-03 16:33 - 16:45 KST — 동일 API host들에서 DB 지연 요청 다수 관측 (duration > 30 s, db > 10 s인 요청 포함)
4. 2026-07-03 16:33 KST 이후 — error-sweeper collector가 latency cluster로 fingerprint 생성

Error Log#

Datadog Traces

{
  "message": "[200] GET /api/v1/levels (Api::V1::LevelsController#index)",
  "controller": "Api::V1::LevelsController",
  "action": "index",
  "duration": 18610.33,
  "db": 7204.3,
  "view": 0.09,
  "serialization": { "duration": 1661 },
  "params": {
    "per_page": "100",
    "page": "1",
    "fields": ["id","name","facility","created_at","updated_at","elevation","ceiling_height","is_ground_level","default_floorplan","permission","meta"],
    "facility_key": "10ofni"
  },
  "team": { "domain": "tpc", "id": 778 },
  "http": { "status_code": 200, "method": "GET" },
  "request_id": "d2debec6-6010-4fc1-8fec-58ef26f7b33c"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-03 16:33 KST
• 최근 발생: 2026-07-03 16:33 KST
• avg / max duration: 18627 ms / 18627 ms

Root Cause Summary#

Api::V1::LevelsController#index는 LevelRepository#_search가 Elasticsearch로 Level을 조회한 뒤, BaseRepository#search가 그 결과에 default_joins(facility, workspace)와 permission_joins(13개 LEFT JOIN + GROUP BY id + GREATEST/IFNULL 매트릭스)를 덧붙여 MySQL에 재조회하는 구조다. 관측 요청은 per_page=100, facility_key=10ofni(활발한 facility)로 permission_joins의 조인 폭이 크게 확장되었고, 동시에 fleet-wide DB 지연 구간에 겹쳐 DB에서만 7204 ms를 소비했다. 나머지 latency는 ES 응답 대기와 ActiveRecord materialization, serialization(1661 ms)에서 누적되어 총 18627 ms에 도달했다. 즉 root cause는 특정 코드 버그가 아니라, 무거운 permission_joins SQL + 대량 tenant permission row + DB 부하 이벤트의 조합이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/levels_controller.rb:13
• ES 검색: app/repositories/level_repository.rb:386-395 (Level.search(...).paginate(...))
• DB 재조회 및 permission join: app/repositories/base_repository.rb:70-98 → app/repositories/level_repository.rb:105-306
• Failure point (지연 지점): app/repositories/level_repository.rb:143-305 (permission_joins의 대형 LEFT JOIN 매트릭스)

def index
  level_query_option = Cupix::QueryOption::Level.new(get_query_option, params)
  levels = repository_instance.search(level_query_option)

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

search는 BaseRepository#search로 위임되고, 여기서 ES 조회 → DB permission join → SearchResult wrapping이 순차 실행된다.

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

LevelRepository.permission_joins는 review/level/facility/workspace/team 각각의 user/group/system-group permission을 13개의 인라인 SELECT LEFT JOIN으로 붙이고, 최종 WHERE에서 GREATEST(IFNULL(...))를 두 층으로 계산한다. GROUP BY id가 붙어 있어 ES가 반환한 per_page=100 level id 전부에 대해 매트릭스 조인이 발생한다.

record.joins("
  LEFT JOIN (
    SELECT reviews.id AS review_id, 2 AS permission
    FROM reviews
    where reviews.public_access_enabled_at IS NOT NULL
      AND reviews.id = #{sanitized_review_id}
  ) AS review_public_permissions
    ON review_public_permissions.review_id = #{sanitized_review_id}

").group('id').select(_select).where("
  (
    GREATEST(
      IFNULL(facility_user_permissions.permission, 0),
      IFNULL(facility_group_permissions.permission, 0)
    ) = 1
    AND
      GREATEST(
        IFNULL(level_user_permissions.permission, 0),
        IFNULL(level_group_permissions.permission, 0)
      ) > 0
  )
  OR
    ...

Elasticsearch 조회는 pagination 이후 최대 per_page=100 records를 반환하고, 이후 MySQL에서 위 join 매트릭스와 applied_permission MAX aggregation을 처리한다. 이 요청은 per_page=100으로 최댓값이고 facility 10ofni는 tenant tpc의 활성 facility(같은 window에 spacetimes 등 다수 endpoint 히트)여서 permission 관련 subquery 폭이 컸다.

기대 동작: #index가 일반 부하에서 50-1000 ms 내 완료 (같은 5분 window에서 대부분 요청은 55-655 ms, db 8-250 ms). 실제 동작: 관측 요청은 db 7204 ms + non-DB(ES 응답 대기 + AR materialization) ~9744 ms + serialization 1661 ms = 18610 ms.

Log Evidence#

Datadog query (재현 가능):

service:cupixworks-api @controller:"Api::V1::LevelsController" @action:"index" @duration:>5000

시간 범위: 2026-07-03T07:00:00Z - 2026-07-03T08:30:00Z.

Result: 3건. 그중 관측 대상은 @timestamp: 2026-07-03T07:33:32.095Z, duration: 18610.33, db: 7204.3.

같은 시간대 fleet-wide DB 지연 확인 query:

service:cupixworks-api status:info @db:>3000

시간 범위: 2026-07-03T07:20:00Z - 2026-07-03T07:45:00Z. 요약(원본 로그 발췌):

2026-07-03T07:33:32.095Z  duration=18610.33  db= 7204.30  LevelsController#index  (본 cluster)
2026-07-03T07:33:39.655Z  duration=67058.08  db=20635.28
2026-07-03T07:33:44.121Z  duration=37934.75  db= 8067.59
2026-07-03T07:34:17.721Z  duration=166727.35 db=26569.18
2026-07-03T07:34:39.756Z  duration=53791.65  db=14092.02
2026-07-03T07:44:36.920Z  duration=47819.40  db=14109.03
2026-07-03T07:44:04.854Z  duration=36409.17  db=10361.06  facility_key=10ofni
2026-07-03T07:44:06.859Z  duration=17178.23  db= 4710.27  facility_key=10ofni
2026-07-03T07:43:42.804Z  duration=15861.50  db= 4386.88  facility_key=10ofni

동일 host ip-10-1-80-134.us-west-2.compute.internal에서 정상 요청 baseline (#index):

2026-07-03T07:37:58.488Z  duration=436.39   db=43.21   facility_key=crp1vu
2026-07-03T07:37:58.487Z  duration=533.42   db=16.32   facility_key=533wrh
2026-07-03T07:37:58.487Z  duration=340.76   db=20.99   facility_key=533wrh

Baseline은 대부분 db < 250 ms, duration < 700 ms. 07:33 관측 값은 baseline 대비 db ~30-300배, duration ~30배.

Status-board 확인 (사전 조회 결과):

scope: svc:cupixworks-api::unknown
active: 2026-07-03-svc-cupixworks-api--unknown-1 (open, started 2026-07-03T08:08:35.753Z)
recent (7d): 6건의 resolved svc:cupixworks-api::unknown incidents

7일 내 cupixworks-api service degraded 계열이 6회 반복되어, DB/ES 자원 지연으로 인한 재발성 성능 이슈임을 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 별도 코드 변경 없이 fleet-wide DB 지연 이벤트의 재발 여부를 우선 확인한다. status-board svc:cupixworks-api::unknown incident (2026-07-03-svc-cupixworks-api--unknown-1)의 다른 cluster들과 상관 분석 필요.
• RDS cupixworks-api primary의 07:33-07:45 UTC 구간에 대해 CPUUtilization, DBLoad, WriteLatency, DeadlockCount, Aborted_clients metric을 확인. Datadog에 metric이 없다면 AWS RDS Performance Insights에서 top SQL로 permission_joins 계열 쿼리가 상위인지 확인.

단기 개선 (1주 이내)#

• LevelRepository.permission_joins (app/repositories/level_repository.rb:105-306): 13개 LEFT JOIN을 유지하되, WHERE의 이중 GREATEST(IFNULL(...)) 매트릭스를 HAVING 절이나 애플리케이션 후처리로 옮기고, 각 permission subquery에 LIMIT 1 및 필요한 index (review_permissions(accessor_id, accessor_type, review_id), level_permissions(level_id, accessor_id, accessor_type), facility_permissions(facility_id, accessor_id, accessor_type), workspace_permissions(workspace_id, accessor_id, accessor_type), team_permissions(team_id, accessor_id, accessor_type)) 유무를 확인. 이미 있으면 통계/카디널리티만 재확인.
• per_page 상한을 #index에서 명시적으로 clamp. 현재는 100까지 허용되지만 permission_joins 비용이 record 수에 선형 이상으로 증가할 수 있음. 서버 측 default를 30으로 낮추거나, 100 요청 시 warning 로깅으로 실제 사용 패턴 확인.
• serialization.duration: 1661 ms 지점 조사. LevelSerializer (app/serializers/level_serializer.rb 계열)에서 permission, default_floorplan 등 fields가 각 level 당 추가 쿼리를 발생시키는지 (Bullet gem 로그) 확인. N+1이 발견되면 default_joins에 preload 추가.

장기 개선 (재발 방지)#

• Permission 계산을 요청 시점 인라인 join에서 분리. 예: (a) 자주 변하지 않는 tenant permission을 캐시 (Redis, TTL 1-5 분), (b) 대량 read 경로에는 요약된 permission projection 테이블을 도입, (c) ES document에 applied_permission을 미리 저장하여 DB 재조회 자체를 제거.
• cupixworks-api service degraded 계열 incident가 지난 7일간 6회 재발 (status-board 확인). API-side 코드 수정만으로는 부족하며 DB (Aurora Reader/Writer split, connection pool 조정, slow query log) 인프라 레벨 대응이 필요. cupix-infrastructure 리포지토리에서 RDS instance class 및 max_connections 검토.
• controller-level p95 latency SLO 도입 (Api::V1::LevelsController#index p95 < 1500 ms 등). 위반 시 자동 alert.

Monitoring#

Datadog dashboard timeseries widget에 그대로 붙일 수 있는 query (writing-datadog-monitoring-queries skill 준수, monitor-only 문법 미사용):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#index}.rollup(avg, 60)

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#index}.rollup(avg, 60)

avg:trace.mysql.query.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#index}.rollup(avg, 60)

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::levelscontroller#index,http.status_code:200}.as_rate()

Alert (모니터 정의는 별도, dashboard widget 아님): p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#index} 가 10분간 > 3000 ms 지속되면 warn.

Risk Assessment#

• Risk level: medium (단일 표본이지만 동시간대 fleet-wide DB 지연 및 7일간 6회 재발과 상관)
• 예상 복잡도: standard (즉시 조치는 관측/확인, 단기 개선은 SQL/index 튜닝, 장기 개선은 아키텍처 변경 필요)