RCA: Api::V1::FacilitiesController#spacetimes 11.6s latency

Overview#

What Happened#

2026-07-09 12:32 KST에 cupixworks-api production(us-west-2)에서 GET /api/v1/facilities/umphr6/spacetimes 요청 1건이 11,652ms 만에 200으로 응답했다. 대상 facility 는 PCL Construction 팀 소유의 "New St. Paul's Hospital - Phase 1A"(id=9486, key=umphr6)로 records 498건이 연결된 대형 프로젝트다. 동일 endpoint 는 지난 24시간 max latency 109s, 평균 1.45s 로 tail latency 가 지속적으로 크게 튀는 상태이며, 이번 이벤트는 그 tail 의 한 sample 이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-09 12:32 KST — Slow 요청 발생 (trace 3680265171956490137), 11,652ms 소요 후 200 응답.
2. 2026-07-09 12:32 KST — error-sweeper collector 가 latency cluster 2e5b8b59-... 로 fingerprint 등록 (first_seen == last_seen).
3. 2026-07-09 12:34–13:29 KST — 동일 facility(umphr6)에 대해 초당 다수(30초 window 안에 95건, 1초당 최대 ~6.15 rps) polling 관측.
4. 2026-07-09 13:38 KST — RCA 착수. Datadog trace/metric 및 tesla repo 코드 확인.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FacilitiesController#spacetimes",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11652,
  "max_ms": 11652,
  "sample_trace_id": "3680265171956490137"
}

관련 access log (trace_id 매칭):

[200] GET /api/v1/facilities/umphr6/spacetimes (Api::V1::FacilitiesController#spacetimes)
timestamp: 2026-07-09 12:32:52 KST

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (샘플 trace), 다만 동일 endpoint tail latency 는 광범위 (24h max 109s)
• 최초 발생: 2026-07-09 12:32 KST
• 최근 발생: 2026-07-09 12:32 KST

Root Cause Summary#

FacilityRepository#spacetimes 가 반환한 ActiveRecord::Relation 을 SpacetimeSerializer 로 렌더링할 때, 각 Spacetime 마다 spacetime.facility 를 참조해 FacilitySerializer 를 인라인 생성한다. 그런데 repository 의 eager_load 는 :record, :level 만 preload 하고 :facility 는 preload 하지 않는다. 결과적으로 N 개의 spacetime 마다 facility 를 lazy load 하는 N+1 쿼리 가 발생하며, per_page 기본값(30) 인 경우에는 paginate 조차 걸지 않아 (facility_repository.rb:74 "Legacy: do not paginate if default per_page used") facility 전체 spacetime 을 한 번에 반환한다. facility 규모(records 498건)와 초당 다회 polling 이 겹치면서 individual request 가 11초 대까지 튀었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/facilities_controller.rb:30 — FacilitiesController#spacetimes
• Query build: app/repositories/facility_repository.rb:31-90 — FacilityRepository#spacetimes
• Serialization: app/serializers/spacetime_serializer.rb:3-49 — SpacetimeSerializer
• Failure surface: N+1 per spacetime on spacetime.facility + 무-pagination 기본 경로

Repository 는 record, level 만 eager_load:

def spacetimes(query_option)
  spacetimes = @model.spacetimes.eager_load(:record, :level).where('levels.cycle_state in (?)', %w[created archiving archived])

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

Default per_page(30) 이면 pagination 자체를 skip 해서 relation 전체가 렌더 대상으로 넘어간다:

pagination = nil
# Legacy: do not paginate if default per_page used until frontend is ready
if query_option.per_page.present? && query_option.page.present? && query_option.per_page != 30
  spacetimes = spacetimes.paginate(page: query_option.page, per_page: query_option.per_page)
  pagination = {
    total_entries: spacetimes.total_entries,
    total_pages: spacetimes.total_pages,
    per_page: spacetimes.per_page,
    previous_page: spacetimes.previous_page,
    current_page: spacetimes.current_page,
    next_page: spacetimes.next_page
  }
end

Serializer 는 spacetime 마다 별도 serializer 3개를 인라인으로 인스턴스화하고, spacetime.facility 는 preload 대상이 아니라 lazy load 됨:

attribute :id
attribute :facility do |spacetime|
  FacilitySerializer.new(spacetime.facility, {
    fields: {
      facility: %w[id name]
    }
  }).serializable_hash[:data][:attributes]
end
attribute :record do |spacetime|
  RecordSerializer.new(spacetime.record, {
    fields: {
      record: %w[id name captured_at note updated_at]
    }
  }).serializable_hash[:data][:attributes]
end
attribute :level do |spacetime|
  LevelSerializer.new(spacetime.level, {
    fields: {
      level: %w[id name is_ground_level elevation has_workareas has_rooms]
    }
  }).serializable_hash[:data][:attributes]
end

기대 동작: 서버는 spacetime 목록을 안정적인 sub-초 latency 로 반환해야 하며, 관련 association 은 한 번씩만 preload 되어야 한다.

실제 동작: N spacetime × facility 1건 lazy query + serializer allocation 오버헤드 + 페이지네이션 부재 → 대형 facility(records 498, spacetime 다수)에서 요청당 latency 가 수 초 ~ 수십 초 범위로 확장된다.

Log Evidence#

Trace 매칭 쿼리:

service:cupixworks-api trace_id:3680265171956490137

결과 (1건):

{
  "timestamp": "2026-07-09 12:32:52 KST",
  "status": "info",
  "message": "[200] GET /api/v1/facilities/umphr6/spacetimes (Api::V1::FacilitiesController#spacetimes)"
}

폴링/부하 확인 쿼리:

service:cupixworks-api "facilities/umphr6/spacetimes"

• 2026-07-09 12:32:30–12:33:00 KST 30초 window 에 95건 요청 관측
• 2026-07-09 13:29:57–13:29:59 KST 3초 window 에 20건 이상 동시 요청

Endpoint latency baseline (24h, resource_name=api::v1::facilitiescontroller_spacetimes):

max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::facilitiescontroller_spacetimes}

• max_latency_s: 109.470552 (24h)
• avg_latency_s: 1.4535
• non-null 5분 bucket 수: 288

Hit rate:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::facilitiescontroller_spacetimes}.as_rate()

• max_rate_rps: 6.15
• avg_rate_rps: 0.377

Facility 규모 확인 (Kibana):

GET records/_search { "term": { "facility.id": 9486 } }

• 498 records 매칭 (facility umphr6 = "New St. Paul's Hospital - Phase 1A", team.id=739 PCL Construction).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/facility_repository.rb:32 의 eager_load(:record, :level) 을 eager_load(:record, :level, :facility) 또는 preload(:facility).eager_load(:record, :level) 로 변경해 serializer 의 spacetime.facility 접근에서 발생하는 N+1 을 제거.
  • 근거: SpacetimeSerializer#facility 블록이 매 record 마다 spacetime.facility 를 dereference 한다. preload 없이 N 번 SELECT 되고 있어 N+1 이 확정됨.
• app/repositories/facility_repository.rb:74 의 query_option.per_page != 30 legacy guard 는 frontend readiness 를 조건으로 두고 있으므로, 프런트엔드 담당자와 협의해 기본 pagination(default per_page, e.g. 30) 을 항상 적용하도록 정리. 대형 facility 에서 한 페이지에 전체 spacetime 을 반환하는 문제를 근본적으로 제거.

단기 개선 (1주 이내)#

• SpacetimeSerializer 에서 FacilitySerializer.new(...).serializable_hash 를 매 record 마다 인스턴스화하는 패턴을 검토. FastJSONAPI 의 has_one/belongs_to relationship + include 옵션, 또는 캐시된 attribute helper 로 대체해 per-record allocation cost 축소.
• Api::V1::FacilitiesController#spacetimes 에 request-scoped ETag/Last-Modified 또는 서버측 short TTL cache 를 걸어, 클라이언트 폴링(관측 6.15 rps peak) 이 매번 전체 목록을 재계산하지 않도록.

장기 개선 (재발 방지)#

• Rails N+1 자동 탐지(bullet gem 또는 request-level assertion) 를 CI/staging 에 도입해 유사 회귀를 조기 발견.
• Frontend 폴링 패턴을 pub/sub 또는 push-based update (SSE/WebSocket, 또는 상태변화 시에만 refetch) 로 이관 검토. 현재 관측된 초당 6+ rps polling 은 tail latency 를 증폭시키는 구조적 부하다.
• paginate legacy guard 처럼 조건부로 pagination 이 skip 되는 endpoint 를 audit 하여, "무한 페이지" endpoint 목록을 문서화하고 순차적으로 제거.

Monitoring#

• Datadog 대시보드에 다음 timeseries widget 을 추가한다:

max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::facilitiescontroller_spacetimes}

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

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::facilitiescontroller_spacetimes}.as_rate()

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::facilitiescontroller_spacetimes}

• p95 > 3s 상태가 10분 이상 지속되면 알림 (Rails endpoint SLO 채널).
• 배포 후 최소 24시간 동안 위 4개 widget 을 관찰하여 max/p95 latency 하락 여부 확인.

Risk Assessment#

• Risk level: medium
  • endpoint 는 200 응답 자체는 유지하지만, 대형 facility 의 폴링 클라이언트에서 UX 저하(수 초~수십 초 대기) 유발.
• 예상 복잡도: standard
  • 즉시 조치는 preload 한 줄 추가 수준으로 low. Pagination legacy guard 제거는 frontend 협의 필요.