RCA: Api::V1::ReviewsController#spacetimes latency (avg 75181ms, max 75181ms)

Overview#

What Happened#

2026-06-26 11:04 KST 무렵 cupixworks-api 의 GET /api/v1/reviews/:key/spacetimes 요청 1건이 75.18 초간 실행된 뒤 완료되었다. 응답은 성공(200)으로 기록되었으며 동일 endpoint 의 다른 요청 다수는 정상 (≤2s) 시간 안에 처리되었으므로 서비스 전반 장애가 아닌 단일 long-running 트랜잭션 이다. APM duration filter (@duration:>500ms) 에 잡혀 latency 클러스터로 수집되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-26 10:25 KST — 동일 service::unknown scope incident open (2026-06-26-svc-cupixworks-api--unknown-1, status board 참조). 본 클러스터는 이 incident 의 일부 컨텍스트로 묶이지만 다른 클러스터들과 fingerprint 가 다르다.
2. 2026-06-26 11:03:14 KST — 문제의 spacetimes 요청 시작 (075s 역산, trace 종료 시각 기준).
3. 2026-06-26 11:04:29 KST — 요청 종료, APM duration 75181ms 기록 (cluster first_seen/last_seen).
4. 2026-06-26 11:05:48 KST — 이후 같은 review 키 (6oba41) 에 대한 /spacetimes 호출이 정상적으로 200 응답 (Datadog 로그 2026-06-26T02:05:48.775Z).

Error Log#

Datadog Logs

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

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-26 11:04 KST
• 최근 발생: 2026-06-26 11:04 KST

사용자 영향: 1명. 동일 endpoint 의 다른 요청은 같은 시간대에 sub-second ~ few-second 로 정상 응답하였다 (Datadog 로그 evidence 참조). 사용자 측면에서는 응답이 거의 75s 후 도착하여 client timeout (browser/CDN default 30~60s) 에 걸렸을 가능성이 높다.

Root Cause Summary#

Api::V1::ReviewsController#spacetimes 는 응답 본문에 페이지 분할된 spacetime 목록을 반환하지만, 내부적으로 두 단계의 무거운 작업 을 직렬로 수행한다. (1) Elasticsearch 에서 review 의 접근 가능한 record_ids 와 level_ids 를 size: 10000 으로 일괄 조회하고 (AccessibleEntitiesRepository::Review#accessible_records / #accessible_levels), (2) 반환된 ID 배열을 PostgreSQL WHERE record_id IN (...) AND level_id IN (...) 절에 그대로 끼워넣은 후 eager_load(:facility, :record, :level) 로 3-way LEFT OUTER JOIN 을 실행한다. 특정 review (예: date_ranges=any 이고 facility 에 record 수가 매우 많은 경우) 에서는 IN 리스트가 수천 개 단위가 되어 Postgres planner 가 hash join → nested loop 로 fallback 하거나 통계가 stale 인 경우 sequential scan 으로 빠지면서 단일 쿼리가 수십 초까지 늘어난다. 본 트레이스 (75.18s) 는 정상 응답 시간 (대다수 < 2s) 대비 50x 이상으로, 동일 시점 다른 spacetimes 요청은 정상 응답한 점이 cluster-wide DB/ES 장애가 아닌 review 특이성에 의한 worst-case 쿼리 플랜 임을 가리킨다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/reviews_controller.rb:37 (#spacetimes)
• Repository call: app/repositories/review_repository.rb:115 (ReviewRepository#spacetimes)
• ES fetch helpers (cache wrapper): app/repositories/concerns/cachable_repository/review.rb:8 (_level_ids), :16 (_record_ids)
• ES query bodies: app/repositories/concerns/accessible_entities_repository/review.rb:24 (accessible_records), :83 (accessible_levels)
• Failure point: app/repositories/review_repository.rb:116 — 위 IDs 가 그대로 SQL IN 절에 들어가는 지점

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

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

  if query_option.extra_filter.present?
    if query_option.extra_filter == 'exclude_empty_counts'
      spacetimes.merge!(@model.spacetimes.non_empty_counts)
    end
  end

  # ... from_at / to_at / record_ids / level_ids 추가 필터 ...

  spacetimes = spacetimes.paginate(page: query_option.page, per_page: query_option.per_page)

  SearchResult.new({
    contents: spacetimes,
    pagination: { ... }
  })
end

@model.spacetimes 는 Review has_many :spacetimes, through: :facility (app/models/review.rb:32) 이므로 SQL 은 facilities → spacetimes 조인이고, 여기에 eager_load(:facility, :record, :level) 가 더해져 4개 테이블 LEFT OUTER JOIN 이 된다. paginate(per_page: 30) 가 마지막에 LIMIT/OFFSET 을 붙이지만, planner 가 inner 결과 set 을 결정하기 위해서는 IN 필터를 우선 평가하여야 한다.

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}", ...)
    level_ids(visibility: visibility)
  end
end

def _record_ids(from_at: nil, to_at: nil, visibility: Cyclable.visibility[:UNTRASHED])
  _cache_key = cache_key('record_ids').merge!({ from_at: from_at, to_at: to_at, visibility: visibility })
  Rails.cache.fetch(_cache_key, expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
    Cupix::Logger.info("Flushing record_ids on review #{model.key}", ...)
    record_ids(from_at: from_at, to_at: to_at, visibility: visibility)
  end
end

캐시 miss 시 ES 호출이 일어난다.

def accessible_records(from_at: nil, to_at: nil, visibility: Cyclable.visibility[:UNTRASHED])
  query_option = Cupix::QueryOption::Record.new(visibility: visibility)
  # ... facility.id, captured_at range filter 추가 ...
  search_results = ::Record.search(query_option.serializable_hash.merge(size: 10000)).records
  Cupix::Logger.info("accessible_entity_count: #{search_results.results.size}", ...)
  search_results
end

size: 10000 은 ES 의 index.max_result_window 한계이며 facility 의 모든 record 를 한 번에 끌어오겠다는 의도다. 반환된 record 개수가 수천 단위로 커지면 다음 PostgreSQL 쿼리가 폭발한다.

기대 동작 vs 실제 동작:

• 기대: ES에서 ID 목록을 한 번에 받아 와 single SQL 로 pagination 된 30개의 spacetime 반환, 응답 < 2s.
• 실제: 특정 review (date_ranges any + 많은 records/levels) 에서 IN 리스트가 수천 ID 단위로 길어져 PostgreSQL JOIN 비용이 수십 초로 폭증. 캐시 miss 가 겹치면 ES 라운드트립 2회 (10000 documents x 2 fields) 도 추가 비용이 된다.

Log Evidence#

Cluster 의 트레이스 ID 검색:

service:cupixworks-api @dd.trace_id:3182898751509851438

결과: 0건 — APM trace 는 Datadog APM Trace Explorer 에서만 조회 가능하며 Log Search 에서는 매칭되지 않았다. (uncertain — needs verification via APM UI for span breakdown)

같은 endpoint 의 정상 응답 (시간 윈도우 02:00-02:10 UTC, KST 11:00-11:10):

service:cupixworks-api "ReviewsController#spacetimes"

샘플 응답 (모두 status:info, 200):

2026-06-26T02:04:28.957Z  [200] GET /api/v1/reviews/6oba41/spacetimes
2026-06-26T02:05:26.991Z  [200] GET /api/v1/reviews/6oba41/spacetimes
2026-06-26T02:05:48.775Z  [200] GET /api/v1/reviews/6oba41/spacetimes
2026-06-26T02:05:56.185Z  [200] GET /api/v1/reviews/nzpzoj/spacetimes
2026-06-26T02:07:49.492Z  [200] GET /api/v1/reviews/h6eiru/spacetimes
2026-06-26T02:08:24.966Z  [200] GET /api/v1/reviews/kqwqfb/spacetimes
2026-06-26T02:08:38.309Z  [200] GET /api/v1/reviews/x4jsco/spacetimes
2026-06-26T02:09:00.137Z  [200] GET /api/v1/reviews/nudfsf/spacetimes

문제의 트레이스는 02:04:29.309Z 에 종료되었으며 (cluster last_seen) 75.18s 길이 → 시작 02:03:14Z. 같은 분(02:03) 의 다른 spacetimes 호출 (/reviews/h6eiru/spacetimes 02:03:4347 사이 십수 건) 은 모두 정상 응답하였으므로 DB/ES 의 cluster-wide slowness 가 아니라 개별 review 의 데이터 분포 차이 임을 시사한다.

같은 시간대 API 에러 (참고용, 본 cluster 와 무관함):

service:cupixworks-api status:error

2026-06-26T02:04:32.077Z  [Integration] Failed to get OPC API access token for integration(1849): 409 Conflict
2026-06-26T02:08:02.095Z  (same OPC error, repeating)

OPC (Oracle integration) 오류는 외부 SaaS 의 service instance stop (ICS-11388) 으로 별개 사안이며 본 spacetimes endpoint 코드 경로와 무관하다.

상태 보드 결과 (동일 service 의 active incident, 본 cluster 는 다른 fingerprint 의 컨텍스트 정보):

2026-06-26-svc-cupixworks-api--unknown-1 (open) — cupixworks-api service degraded
  started_at: 2026-06-26T01:25:34Z
  cluster_ids: 7 (이 cluster 는 fingerprint 가 달라 미포함)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 본 latency 트레이스의 APM span breakdown 을 Datadog APM Trace Explorer 에서 trace_id=3182898751509851438 로 직접 확인하여, 75s 중 pg.query / elasticsearch.query / Ruby 가 차지하는 비율을 분리. PostgreSQL span 이 대부분을 차지하면 H1 이 확정.
• 문제의 review key 를 식별 후 (트레이스의 http.url 에서) 해당 review 의 selected_levels/date_ranges 와 facility 의 records 수를 확인. 동일 review 가 반복적으로 slow 한지 (recurring) 일회성인지 판단.

단기 개선 (1주 이내)#

• app/repositories/review_repository.rb:116 의 spacetimes 쿼리에서 ID 배열의 cardinality 가 일정 임계값 (예: 1000) 을 초과하면 WHERE IN (...) 대신 subquery / temp table 또는 record_id BETWEEN 형식의 batched query 로 분리해서 plan 안정성을 확보하는 방향 검토.
• eager_load(:facility, :record, :level) 가 정말 모든 응답 필드에 필요한지 점검. SpacetimeSerializer 가 사용하는 association 만 preload 로 바꾸면 JOIN 비용을 줄일 수 있다 (eager_load → preload 는 single-query JOIN 을 multi-query 로 바꾸지만 큰 IN 절에서는 더 빠를 수 있다).
• accessible_records / accessible_levels 의 size: 10000 은 ES 가 단일 응답으로 보낼 수 있는 최대 size 이다. 실제로 한 review 가 그 정도 record 수를 가질 경우, controller 에서 timeout/페이지네이션을 강제하거나 review schema 단에서 record 수 상한을 두는 방향 검토.

장기 개선 (재발 방지)#

• ReviewsController#spacetimes 가 사실상 spacetime 목록을 페이지네이션해서 반환하지만, 내부적으로는 전체 record_ids / level_ids 를 끌어오는 구조다. 페이지네이션 의도와 백엔드 비용이 불일치 — review 의 spacetime 인덱스를 ES 에 별도 색인하여 SQL JOIN 대신 ES 페이지네이션으로 처리하는 방향이 근본 해법.
• APM 에서 Api::V1::ReviewsController#spacetimes 의 p95/p99 latency 를 SLO 로 관리하고 (예: p95 < 3s), 임계 초과 시 자동 알림.

Monitoring#

추가할 메트릭/알림 — Datadog timeseries widget 용 쿼리:

p95 latency of the endpoint:

p95:trace.rack.request{service:cupixworks-api,resource_name:Api::V1::ReviewsController#spacetimes}

요청 수 (rate):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::ReviewsController#spacetimes}.as_rate()

duration > 10s 인 요청 count (slow request burn rate):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::ReviewsController#spacetimes,duration:>10s}.as_count()

Postgres 평균 쿼리 시간 (관련 DB 부하 모니터):

avg:postgresql.query.time{service:cupixworks-api}

알림 임계:

• p95 > 5000ms (5s) for 10분 → warn
• p99 > 30000ms (30s) for 5분 → critical
• 단일 요청 duration > 60s → critical (즉시 페이지)

Risk Assessment#

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

근거: 단일 user 단일 요청 영향이며 같은 시간대 다른 호출은 정상이지만, 동일 endpoint 가 데이터 양에 비례하여 worst-case latency 가 폭증하는 구조적 패턴이라 같은 review 또는 유사 형태 review 에서 재발 가능. 수정은 SQL 전략 변경 + ES size 정책 변경이므로 careful regression test 가 필요하다.