RCA: Api::V1::ReviewsController#load Latency (avg 1284ms, max 1500ms)

Overview#

What Happened#

2026-05-26 05:01~06:07 UTC 사이에 cupixworks-api 서비스의 ReviewsController#load 엔드포인트에서 평균 1284ms, 최대 1500ms의 응답 지연이 us-west-2 및 ap-southeast-2 리전에서 4회 발생했다. HTTP 응답은 모두 200 OK이며 기능적 에러는 없으나, 정상 응답 시간(~100ms) 대비 10배 이상 느린 성능 저하가 관측되었다.

Quick Facts#

Timeline#

1. 2026-05-26T05:01:15Z — 최초 느린 요청 감지 (1218ms, review key 7rvsjs, us-west-2)
2. 2026-05-26T05:11:27Z — 두 번째 느린 요청 (1136ms, review key ff1mxf, us-west-2)
3. 2026-05-26T05:22:22Z — 최대 지연 요청 (1496ms, review key h61g4o, ap-southeast-2)
4. 2026-05-26T06:07:28Z — 마지막 느린 요청 (1276ms, review key a73lse, us-west-2)
5. 2026-05-26T06:07:30Z — 클러스터 종료 시점

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ReviewsController#load",
  "service": "cupixworks-api",
  "occurrences": 4,
  "avg_ms": 1284,
  "max_ms": 1500,
  "sample_trace_id": "3844391472966001954"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 4
• 최초 발생: 2026-05-26T05:01:15.236Z
• 최근 발생: 2026-05-26T06:07:28.447Z
• 영향 범위: 4명의 사용자 (서로 다른 팀/facility)에서 Review 로드 시 1초 이상의 응답 지연 경험. 기능적 장애는 없으나 UX 저하 발생.

Root Cause Summary#

ReviewsController#load 요청 시 facility-level Redis 캐시가 무효화된 상태에서 compute_load_info가 실행될 때, _level_ids와 _record_ids 메서드가 Elasticsearch에 size: 10000 쿼리를 순차적으로 실행한다. 이 Elasticsearch 쿼리 시간은 Rails의 DB 시간 계측에 포함되지 않아 "unaccounted time"으로 나타나며, 대규모 facility에서 두 ES 쿼리가 각각 수백 ms씩 소요되어 총 1초 이상의 지연이 발생한다. 이후 14개의 개별 exists? DB 쿼리가 순차 실행되어 추가 지연을 누적시킨다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/reviews_controller.rb:95-106

def load
  fresh = params[:fresh].present? && ActiveRecord::Type::Boolean.new.cast(params[:fresh])
  load_info = repository_instance.load(fresh: fresh)

  render_api Renderable.new({
    contents: @model,
    serializer: ReviewLoadSerializer,
    serializer_option: {
      params: { load_info: load_info }
    }
  })
end

• Cache decision logic: app/repositories/review_repository.rb:18-105

# Check if facility-level cache is valid
facility_cache_valid = Rails.cache.read(facility_cache_key)

facility 캐시가 invalid 상태이면 compute_load_info를 라이브로 실행하고, 결과를 다시 캐시에 저장한다 (lines 81-104).

• Failure point (성능 병목): app/repositories/review_repository.rb:558-585

def compute_load_info
  level_ids = _level_ids        # ← Elasticsearch query (size: 10000)
  record_ids = _record_ids      # ← Elasticsearch query (size: 10000)
  facility_id = @model.facility_id

• Elasticsearch 쿼리 (levels): app/repositories/concerns/accessible_entities_repository/review.rb:83-107

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

• Elasticsearch 쿼리 (records): app/repositories/concerns/accessible_entities_repository/review.rb:24-62

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

• 14개 순차 exists? 쿼리: app/repositories/review_repository.rb:563-584

{
  assets: ::Asset.where(assetable_type: 'Review', assetable_id: @model.id, cycle_state: 'created').exists?,
  measurements: @model.measurements.where(cycle_state: 'created').exists?,
  bookmarks: {
    me: current_user.present? ? ::Bookmark.where(review_id: @model.id, user_id: current_user.id).exists? : false,
    team: ::Bookmark.where(review_id: @model.id).where.not(user_id: current_user&.id).exists?
  },
  spacetimes: @model.spacetimes.where(level_id: level_ids, record_id: record_ids).exists?,
  # ... 10 more exists? queries
}

기대 동작: facility 캐시가 유효하면 Redis에서 1~5ms 내에 load_info를 반환. 실제 동작: facility 캐시가 무효화될 때마다 2개의 ES 쿼리 + 14개 DB 쿼리가 순차 실행되어 1000ms+ 소요. 캐시 키에 facility.entity_updates_hexdigest가 포함되어 있어 facility 엔티티가 변경될 때마다 캐시가 무효화됨.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "ReviewRepository#load"

LIVE_FACILITY_INVALIDATED 로그 (느린 요청과 시간 일치):

{
  "message": "ReviewRepository#load | review_id=4188 | facility_id=1193 | cache_source=LIVE_FACILITY_INVALIDATED | compute_time=1412.99ms | total_time=1423.13ms",
  "repository_class": "ReviewRepository",
  "function": "load",
  "cache_source": "LIVE_FACILITY_INVALIDATED",
  "review_id": 4188,
  "facility_id": 1193,
  "compute_time": 1412.99,
  "elapsed_time": 1423.13
}

Request 로그에서 DB 시간 vs 전체 시간 비교:

duration=1496ms, db=191ms (13%), unaccounted=1305ms (87%) — review key h61g4o
duration=1276ms, db=195ms (15%), unaccounted=1081ms (85%) — review key a73lse
duration=1218ms, db=122ms (10%), unaccounted=1096ms (90%) — review key 7rvsjs
duration=1136ms, db=49ms  (4%),  unaccounted=1087ms (96%) — review key ff1mxf

캐시 경로별 성능 통계 (3시간 윈도우, 200건):

"unaccounted time"의 87-97%는 Elasticsearch 쿼리 시간이다. ES 쿼리는 ActiveRecord instrumentation에 포함되지 않으므로 Rails의 db 메트릭에 잡히지 않는다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/concerns/accessible_entities_repository/review.rb:57 및 :102 — Elasticsearch 쿼리에 size: 10000 대신 _source: false를 사용하여 ID만 반환하도록 최적화. compute_load_info에서는 level_ids와 record_ids 배열만 필요하므로 전체 document를 로드할 필요 없음.
• app/repositories/review_repository.rb:558-561 — _level_ids와 _record_ids를 병렬로 실행 (예: Concurrent::Future 또는 Thread). 두 ES 쿼리는 서로 독립적이므로 병렬 실행 시 최대 50% 시간 절감 가능.

단기 개선 (1주 이내)#

• compute_load_info의 14개 exists? 쿼리를 단일 쿼리로 통합하거나 UNION ALL로 배치 처리. 현재 순차 실행으로 인해 각 쿼리의 네트워크 라운드트립이 누적됨.
• CachableRepository::Review의 _level_ids, _record_ids 캐시에서 facility.entity_updates_hexdigest 의존성을 분리. 현재 facility의 어떤 엔티티 변경이든 모든 review의 level/record ID 캐시를 무효화하는데, 대부분의 변경은 level/record에 영향을 미치지 않음.

장기 개선 (재발 방지)#

• compute_load_info 결과를 비동기로 사전 계산하는 background job 도입. Facility 엔티티 변경 시 즉시 캐시를 무효화하는 대신, 변경 이벤트를 큐에 넣고 백그라운드에서 새 값을 미리 계산하여 캐시에 저장 (cache warming).
• Elasticsearch 쿼리에 대한 APM instrumentation 추가. 현재 ES 쿼리 시간이 "unaccounted"로 분류되어 모니터링 사각지대.

Monitoring#

• compute_load_info 실행 시간에 대한 메트릭 알림 추가 (P95 > 500ms 시 경고)
• Datadog 쿼리 예시:

service:cupixworks-api "ReviewRepository#load" @cache_source:LIVE_FACILITY_INVALIDATED @compute_time:>500

• Elasticsearch 쿼리 시간 추적을 위한 custom metric 또는 APM span 추가 권장

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 기능적 에러 없이 성능 저하만 발생. 캐시가 정상 작동하는 75%의 요청에는 영향 없음. 대규모 facility에서 캐시 무효화 시에만 간헐적으로 발생하는 패턴.