RCA: Api::V1::LevelsController#index Latency (avg 1108ms, max 1267ms)

Overview#

What Happened#

2026-05-26 09:28~12:49 UTC 사이에 cupixworks-api 서비스의 Api::V1::LevelsController#index 엔드포인트에서 평균 1108ms, 최대 1267ms의 응답 지연이 발생했다. us-west-2와 eu-central-1 두 리전에서 총 3건이 감지되었다. 정상 응답 시간 대비 약 10배 느린 수치이다.

Quick Facts#

Timeline#

1. 2026-05-26T09:28:44Z — 최초 느린 요청 감지 (>500ms threshold)
2. 2026-05-26T11:10:00~11:24:00Z — APM 메트릭에서 피크 관측 (평균 380~800ms)
3. 2026-05-26T12:49:07Z — 마지막 느린 요청 감지
4. 2026-05-26T13:00:00Z 이후 — 정상 수준 (~60-100ms)으로 복귀

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::LevelsController#index",
  "service": "cupixworks-api",
  "occurrences": 3,
  "avg_ms": 1108,
  "max_ms": 1267,
  "sample_trace_id": "163954909800504144"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 3
• 최초 발생: 2026-05-26T09:28:44.869Z
• 최근 발생: 2026-05-26T12:49:07.686Z
• 영향 범위: levels 목록 API를 호출하는 모든 사용자. 특히 review 경유 요청(/api/v1/reviews/:key/levels)에서 cache miss 발생 시 체감 지연이 크다.

Root Cause Summary#

LevelsController#index의 review 경로에서 CachableRepository::Review#_level_ids 캐시가 빈번하게 무효화되면서 Elasticsearch + 12-way LEFT JOIN permission 쿼리가 반복 실행되어 응답 지연이 발생했다. 캐시 키에 포함된 facility.entity_updates_hexdigest는 facility 내 10개 엔티티 타입(level, floorplan, capture, record 등) 중 어느 하나라도 업데이트되면 변경되므로, 활발한 facility에서는 캐시가 사실상 작동하지 않는다. 이 시간대에 두 리전에서 동일 review에 대한 동시 요청이 몰리면서 thundering herd 현상이 발생하여 ES와 MySQL 모두에 부하가 집중되었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/levels_controller.rb:13 (#index)
• LevelRepository#search → BaseRepository#search (app/repositories/base_repository.rb:70)
• LevelRepository#_search (app/repositories/level_repository.rb:327)
  • review 경로: ReviewRepository#show + _level_ids 호출 (line 334, 348)
• Cache check: CachableRepository::Review#_level_ids (app/repositories/concerns/cachable_repository/review.rb:8)
• Cache key 계산: cache_key('level_ids') (app/repositories/concerns/cachable_repository/review.rb:90-103)
  • facility.entity_updates_hexdigest 포함 → EntityUpdates::Facility 10개 엔티티 추적
• Cache miss 시: accessible_levels → ES query with size: 10000 (app/repositories/concerns/accessible_entities_repository/review.rb:102)
• Permission joins: 12 LEFT JOINs (app/repositories/level_repository.rb:105-306)

def _level_ids(visibility: Cyclable.visibility[:UNTRASHED])
  Rails.cache.fetch(cache_key('level_ids'), expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
    Cupix::Logger.info("Flushing level_ids on review #{model.key}", class: self.class.name, function: __method__, module: 'CachableRepository::Review', review: { key: model.key })

    level_ids(visibility: visibility)
  end
end

def cache_key(cache_type)
  default_key = {
    self: {
      id: model.id,
      class: model.class.name,
      updated_at: model.updated_at
    },
    cache: cache_type,
    facility_hex_digest: model.facility.entity_updates_hexdigest
  }
  default_key.merge!({ drafted_at: model.drafted_at }) if model.marked_as_draft?

  default_key
end

def entities
  %I[level floorplan sketch annotation_layer bim annotation pointcloud mesh capture record]
end

search_results = ::Level.search(query_option.serializable_hash.merge(size: 10000)).records

기대 동작: _level_ids 캐시가 1주일간 유지되어 ES + DB 쿼리를 건너뛴다. 실제 동작: facility.entity_updates_hexdigest가 facility 내 모든 엔티티 업데이트마다 변경되어 캐시 키가 일치하지 않으며, 매 요청마다 ES(size:10000) + 12-JOIN SQL이 재실행된다.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "Flushing level_ids"

피크 시간대(11:10~11:25 UTC)에 동일 review에 대한 반복 cache miss 확인:

{"timestamp": "2026-05-26 20:17:50 KST", "status": "info", "message": "Flushing level_ids on review dmxd4b", "class": "ReviewRepository", "function": "_level_ids"}
{"timestamp": "2026-05-26 20:17:56 KST", "status": "info", "message": "Flushing level_ids on review dmxd4b", "class": "ReviewRepository", "function": "_level_ids"}
{"timestamp": "2026-05-26 20:17:58 KST", "status": "info", "message": "Flushing level_ids on review dmxd4b", "class": "ReviewRepository", "function": "_level_ids"}
{"timestamp": "2026-05-26 20:18:30 KST", "status": "info", "message": "Flushing level_ids on review dmxd4b", "class": "ReviewRepository", "function": "_level_ids"}

동일 review dmxd4b에 대해 40초 안에 4회 cache miss → thundering herd 패턴.

APM 메트릭 (Datadog 쿼리):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller_index}

정상 시간대 평균: 60160ms. 피크 시간대(11:1011:24 UTC): 308~792ms.

ES 쿼리 duration (동일 시간대):

avg:trace.elasticsearch.query.duration{service:cupixworks-api}

정상: 60-100ms → 피크: 175-260ms (23배 증가).

MySQL 쿼리 duration:

avg:trace.mysql2.query.duration{service:cupixworks-api}

정상: 8-25ms → 피크: 45-100ms (35배 증가).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/concerns/cachable_repository/review.rb:90-103의 cache_key 메서드에서 facility_hex_digest를 제거하거나, 캐시 무효화를 이벤트 기반(explicit invalidation)으로 전환해야 한다. 현재는 캐시 TTL이 1주일이지만 키 자체가 매번 바뀌므로 실질적으로 캐시가 작동하지 않는다.

단기 개선 (1주 이내)#

• Rails.cache.fetch에 race_condition_ttl 옵션 추가하여 thundering herd 완화. 동시 요청 시 stale cache를 짧은 시간 동안 반환하고, 한 프로세스만 refresh하도록 한다.
• accessible_levels의 size: 10000을 실제 필요한 수량으로 제한하거나, IDs만 요청하는 경량 ES 쿼리로 교체 (_source: false, stored_fields: []).

장기 개선 (재발 방지)#

• entity_updates_hexdigest 패턴을 전면 재설계. Facility 내 entity 변경 시 관련 캐시만 선택적으로 무효화하는 이벤트 기반 invalidation (예: after_commit callback에서 특정 캐시 키만 삭제)으로 전환.
• Permission joins를 materialized view 또는 별도 denormalized 테이블로 분리하여 매 요청마다 12-JOIN을 실행하지 않도록 한다.

Monitoring#

• _level_ids cache miss rate 추적:

service:cupixworks-api "Flushing level_ids" | stats count by review.key

• LevelsController p95 latency 알림 설정 (threshold: 500ms):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller_index} > 0.5

• entity_updates_hexdigest 변경 빈도 추적 — 활발한 facility에서 분당 cache invalidation 횟수 모니터링.

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — 캐시 키 구조 변경은 기존 캐시 무효화 로직과 데이터 정합성에 영향을 미치므로 충분한 테스트 필요. 그러나 코드 변경 범위 자체는 cachable_repository/review.rb 한 파일로 제한적.