RCA: ReviewsController#spacetimes Latency (1144ms)

Overview#

What Happened#

2026-05-27 06:16:50 UTC에 cupixworks-api의 Api::V1::ReviewsController#spacetimes 엔드포인트에서 1144ms 지연이 발생했다. DB 시간은 24ms, serialization 8ms에 불과했으나 전체 응답 시간은 1143ms로, 약 1110ms가 애플리케이션 레벨에서 소비되었다. 동일 시간대에 동일 패턴(낮은 DB 시간, 높은 전체 지연)의 요청이 다수 관찰되었다.

Quick Facts#

Timeline#

1. 2026-05-27T06:16:50Z — ReviewsController#spacetimes 요청 시작 (review key: oxk5u6)
2. 2026-05-27T06:16:52Z — 요청 완료 (1143ms, HTTP 200)
3. 2026-05-27T06:17:04-06:17:18Z — 동일 review에 대한 후속 요청들도 높은 지연 관찰 (611ms~1318ms)
4. 2026-05-27T06:16-06:17Z — 다른 review에서도 유사 패턴 관찰 (bmya70 1026ms db=24ms, 2yz40r 1072ms db=12ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ReviewsController#spacetimes",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1144,
  "max_ms": 1144,
  "sample_trace_id": "1230393241228641865"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-05-27T06:16:50.428Z
• 최근 발생: 2026-05-27T06:16:50.428Z

Root Cause Summary#

ReviewsController#spacetimes 요청의 1144ms 지연은 DB 쿼리(24ms)나 serialization(8ms)이 아닌, Elasticsearch를 통한 _level_ids/_record_ids 캐시 미스 시 발생하는 네트워크 라운드트립이 주요 원인이다. CachableRepository::Review의 _level_ids와 _record_ids는 Rails cache hit 시 빠르지만, cache miss 시 Elasticsearch에 size: 10000 쿼리를 2회 실행하며 이 과정에서 ~1000ms 이상의 지연이 발생한다. 동일 시간대에 다른 review들에서도 동일 패턴이 관찰되어 인프라 레벨 지연(GC pause, connection pool 대기) 가능성도 있으나, ES 캐시 미스가 가장 유력한 원인이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/reviews_controller.rb:37
• before_action :set_review → review 로드 (line 10)
• repository_instance.spacetimes(query_option) → ReviewRepository#spacetimes (line 115)
• self._level_ids → ES 쿼리 또는 캐시 (cachable_repository/review.rb:8)
• self._record_ids → ES 쿼리 또는 캐시 (cachable_repository/review.rb:16)
• SQL 쿼리 실행 (eager_load + WHERE IN) → 24ms
• Serialization → 8ms
• Failure point: app/repositories/concerns/cachable_repository/review.rb:9 (cache miss 시 ES 호출)

컨트롤러에서 spacetimes 액션 호출:

def spacetimes
  spacetimes = repository_instance.spacetimes(
    Cupix::QueryOption::Spacetime.new(get_query_option, params)
  )

  render_api Renderable.new({
    search_result: spacetimes,
    is_collection: true,
    serializer: SpacetimeSerializer,
    serializer_option: {
      fields: {
        spacetime: @fields
      }
    }
  })
end

Repository에서 SQL 쿼리 실행 전에 _level_ids, _record_ids를 먼저 가져옴:

def spacetimes(query_option)
  spacetimes = @model.spacetimes.eager_load(:facility, :record, :level).where(level_id: self._level_ids, record_id: self._record_ids)

캐시 미스 시 Elasticsearch로 fallback하여 최대 10,000건을 조회:

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

Elasticsearch 쿼리 (size: 10000):

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

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

기대 동작: 캐시 hit 시 _level_ids/_record_ids는 즉시 반환되어 전체 요청이 ~50ms 이내 완료. 실제 동작: 캐시 miss로 인해 2회의 ES 쿼리가 순차 실행되며 ~1000ms+ 지연 발생. DB 쿼리(24ms)와 serialization(8ms)은 정상 범위.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "ReviewsController" "spacetimes" @duration:>500
Time range: 2026-05-27T05:16:50Z to 2026-05-27T06:46:50Z

해당 요청의 로그:

{
  "timestamp": "2026-05-27T06:16:52.259Z",
  "duration_ms": 1143.06,
  "db_runtime_ms": 24.4,
  "serialization_ms": 8,
  "view_runtime_ms": 0.07,
  "status": 200,
  "method": "GET",
  "path": "/api/v1/reviews/oxk5u6/spacetimes",
  "controller": "Api::V1::ReviewsController#spacetimes",
  "host": "ip-10-1-80-134.us-west-2.compute.internal",
  "user": "hw1213.park@samsung.com",
  "team": "secc",
  "pagination": { "page": 1, "per_page": 100, "total_entries": 30, "total_pages": 1 }
}

동일 패턴의 다른 요청들 (낮은 DB, 높은 전체 지연):

service:cupixworks-api "ReviewsController" "spacetimes" @duration:>1000

[
  { "review": "oxk5u6", "duration_ms": 1143, "db_ms": 24.4, "entries": 30 },
  { "review": "bmya70", "duration_ms": 1026, "db_ms": 24, "entries": 160 },
  { "review": "2yz40r", "duration_ms": 1072, "db_ms": 12, "entries": 4 }
]

이 3건 모두 DB 시간이 극히 짧고 결과 건수도 적어, 지연이 SQL이나 serialization이 아닌 사전 처리(ES 조회 또는 인프라 대기)에서 발생했음을 확인.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/concerns/cachable_repository/review.rb:8-23: _level_ids와 _record_ids 캐시 TTL 및 워밍 전략 검토. 현재 DEFAULT_PERMISSION_CACHE_EXPIRES_IN 값이 짧은 경우 캐시 미스 빈도가 높아질 수 있음.
• 캐시 미스 시 2회의 ES 쿼리가 순차 실행되므로, 병렬 실행(concurrent fetch)으로 변경하면 지연을 절반으로 줄일 수 있음.

단기 개선 (1주 이내)#

• app/repositories/concerns/accessible_entities_repository/review.rb:57,102: ES 쿼리의 size: 10000을 실제 필요한 크기로 제한하거나, ID만 반환하는 경량 쿼리(_source: false, stored_fields: [])로 변경하여 ES 응답 시간 단축.
• app/repositories/review_repository.rb:116: _level_ids와 _record_ids를 Concurrent::Future 또는 Thread로 병렬 조회하여 순차 대기 제거.

장기 개선 (재발 방지)#

• Review 로드 시점에 _level_ids/_record_ids 캐시를 사전 워밍하는 background job 도입. 사용자 첫 접근 전에 캐시가 준비되도록 review 생성/업데이트 시 캐시 갱신.
• spacetimes 테이블에 composite index (facility_id, level_id, record_id) 추가로 대규모 review에서의 DB 성능도 보장.

Monitoring#

• ReviewsController#spacetimes p95 latency 모니터링 추가
• 캐시 미스 비율 추적 (Flushing level_ids/record_ids 로그 빈도)

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

• ES 쿼리 지연 모니터링:

service:cupixworks-api @duration:>500 resource_name:"Api::V1::ReviewsController#spacetimes"

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard