RCA: Api::V1::FeedsController#index latency (18.15s)

Overview#

What Happened#

2026-07-01 16:58 KST에 cupixworks-api (us-west-2)의 GET /api/v1/feeds 한 건이 18.15초 걸려 완료됐다. HTTP 200으로 성공했지만, 응답 시간의 거의 전부(db: 17754.85ms)를 데이터베이스 쿼리가 차지했다. admin 팀 사용자가 facility_key=2f6b5s (해당 facility의 event 3,664건)를 조회한 요청 한 건이 지연 클러스터로 잡혔다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 16:58:29 KST — 요청 진입 (@timestamp - duration 역산; first_seen 2026-07-01T07:58:27.541Z)
2. 2026-07-01 16:58:47 KST — 응답 완료, duration=18148.09ms, db=17754.85ms 기록 (Datadog log @timestamp 2026-07-01T07:58:47.600Z)
3. 2026-07-01 16:58:27 KST — error-sweeper collector가 latency cluster로 감지 (first_seen)

Error Log#

Datadog Logs

{
  "message": "[200] GET /api/v1/feeds (Api::V1::FeedsController#index)",
  "controller": "Api::V1::FeedsController",
  "action": "index",
  "duration": 18148.09,
  "db": 17754.85,
  "view": 0.09,
  "serialization": { "duration": 555 },
  "http": { "status_code": 200, "method": "GET", "url_details": { "path": "/api/v1/feeds" } },
  "params": { "per_page": "100", "facility_key": "2f6b5s",
              "fields": ["id","user","event","recipe","event_object"] },
  "pagination": { "current_page": 1, "per_page": 100,
                  "total_pages": 37, "total_entries": 3664, "next_page": 2 },
  "user": { "id": 39791, "team": { "id": 133 } },
  "team": { "domain": "findorff", "id": 159 },
  "request_id": "29e09de6-e8c5-40e9-9bfb-a50ea649b475",
  "environment": "production"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-01 16:58 KST
• 최근 발생: 2026-07-01 16:58 KST
• HTTP 결과: 200 (성공) — 에러 없음, 응답 지연만 발생

Root Cause Summary#

Api::V1::FeedsController#index가 admin 팀 사용자 요청에 대해 FeedRepository#search → _event_query로 분기하여 MySQL events 테이블을 조회한다. 이 쿼리는 facility_id로 필터 + eventable_type IN (12개 모델) + LEFT OUTER JOIN event_objects + ORDER BY created_at DESC + LIMIT/OFFSET + total_entries를 위한 COUNT를 한 번에 수행한다. db/schema.rb상 events 테이블에는 단일 컬럼 인덱스(index_events_on_facility_id, index_events_on_eventable_type_and_eventable_id)만 있고 (facility_id, eventable_type, created_at) 복합 인덱스가 없어, 대상 facility의 event 수가 3,664건인 이번 요청은 facility_id만으로 인덱스 스캔 후 filesort로 정렬되고 event_objects와 join되며 DB에서 17.75초를 소비했다. 결과셋 크기와 DB 시간이 선형이 아닌 급격한 상관(총 27건 → 74ms vs 3,664건 → 17,755ms)을 보이는 것이 이를 뒷받침한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/feeds_controller.rb:2-11
• Dispatch: FeedRepository#search → current_user.admin_team? 분기 (admin이므로 _event_query 경로)
• Failure point (latency 원인): app/repositories/feed_repository.rb:169-177 (_event_query) — Event.eager_load(:event_objects).where(...).order(created_at: :desc).paginate(...)

Controller는 얇은 wrapper다:

def index
  feed_query_option = Cupix::QueryOption::Feed.new(get_query_option, params)
  feeds = repository_instance.search(feed_query_option)

  render_api Renderable.new(
    search_result: feeds,
    is_collection: true,
    serializer_option: @serializer_option
  )
end

FeedRepository#search에서 admin 사용자는 Elasticsearch 대신 ActiveRecord 경로로 분기한다:

def search(query_option)
  set_query_option(query_option)

  if current_user.admin_team?
    facility = FacilityRepository.new(current_user: self.current_user).show(self.query_option.facility_key)
    contents = _event_query(
      facility_id: facility.id,
      per_page: self.query_option.per_page,
      page: self.query_option.page
    )
    feed_contents = contents.map do |event|
      _event_object_id = event.event_objects.first
      Feed.new({
        event: event,
        event_object_id: _event_object_id
      })
    end

• 참고: admin_team?는 Rails.cache.fetch(..., expires_in: 4.hours)로 캐시된다 (app/models/concerns/properties/user.rb:139-143) — admin 판정 자체는 병목이 아님.

핵심 쿼리는 _event_query다:

def _event_query(params)
  raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'facility_id is required') if params[:facility_id].blank?

  Event.eager_load(:event_objects).where(
    eventable_type: FEED_EVENTABLE_MODEL
  ).where(
    facility_id: params[:facility_id]
  ).order(created_at: :desc).paginate(per_page: params[:per_page], page: params[:page])
end

FEED_EVENTABLE_MODEL는 12종의 polymorphic type이다:

FEED_EVENTABLE_MODEL = %w[AnnotationLayer Annotation Bim Capture
                          Facility Floorplan Level Mesh Pointcloud
                          Record Review Sketch].freeze

이 코드가 MySQL로 만드는 쿼리는 대략 다음과 같다:

SELECT events.*, event_objects.*FROM   eventsLEFT OUTER JOIN event_objects ON event_objects.event_id = events.idWHERE  events.eventable_type IN ('AnnotationLayer','Annotation',...,'Sketch')  AND  events.facility_id = <facility.id>ORDER BY events.created_at DESCLIMIT 100 OFFSET 0;-- plus will_paginate COUNT for total_entries:SELECT COUNT(*) FROM eventsWHERE  eventable_type IN (...) AND facility_id = <facility.id>;

db/schema.rb상 관련 인덱스:

t.index ["eventable_team_id"], name: "index_events_on_eventable_team_id"
t.index ["eventable_type", "eventable_id"], name: "index_events_on_eventable_type_and_eventable_id"
t.index ["facility_id"], name: "index_events_on_facility_id"
t.index ["level_id"], name: "index_events_on_level_id"
t.index ["linked_review_id"], name: "index_events_on_linked_review_id"
t.index ["record_id"], name: "index_events_on_record_id"
t.index ["team_id"], name: "index_events_on_team_id"
t.index ["user_id"], name: "index_events_on_user_id"
t.index ["workspace_id"], name: "index_events_on_workspace_id"

• (facility_id, eventable_type, created_at) 복합 인덱스 부재 — filter+정렬을 한 번에 처리할 수 있는 인덱스가 없다.
• 옵티마이저는 index_events_on_facility_id로 3,664개 행을 잡고, eventable_type IN (…)를 residual filter로 적용한 뒤 created_at DESC로 filesort, 그 후 event_objects와 LEFT JOIN 하는 형태로 실행됐을 가능성이 크다.
• 추가로 paginate가 요구하는 SELECT COUNT(*) 한 방이 같은 인덱스로 다시 실행돼 부담을 이중으로 준다.

기대 동작: 첫 페이지 100건 조회 시 sub-second (관측된 일반 케이스와 유사). 실제 동작: db 시간 17.75s, view: 0.09ms이고 serialization: 555ms뿐이므로 병목은 순수 DB 쿼리에 있음.

Log Evidence#

Datadog 쿼리 (실제 요청 로그):

service:cupixworks-api "FeedsController"

시간 범위: 2026-07-01T07:55:00Z ~ 2026-07-01T08:05:00Z

문제의 요청 payload (raw log 발췌):

{
  "@timestamp": "2026-07-01T07:58:47.600Z",
  "duration": 18148.09,
  "db": 17754.85,
  "view": 0.09,
  "serialization": { "duration": 555 },
  "controller": "Api::V1::FeedsController",
  "action": "index",
  "params": { "facility_key": "2f6b5s", "per_page": "100" },
  "pagination": { "total_entries": 3664, "total_pages": 37, "current_page": 1 },
  "user": { "id": 39791, "team": { "id": 133 } },
  "team": { "domain": "findorff", "id": 159 },
  "http": { "status_code": 200 }
}

동일 admin 사용자(user.id: 39791)의 지난 14일간 FeedsController 호출 5건 비교 — total_entries(대상 facility의 event 수)와 db 시간이 급격히 비선형으로 증가한다:

Datadog 쿼리:

service:cupixworks-api "FeedsController" @user.id:39791

3,664건이 184건 대비 20배지만 db 시간은 189ms → 17,755ms로 93배 증가 — 인덱스가 filter+sort를 커버하지 못하고 filesort/LEFT JOIN 비용이 rows^k (k>1)에 가깝게 붙는 전형적인 pattern.

동일 시간대(±5분) cupixworks-api 서비스에 error/warn 로그 없음 — DB 인프라 전반의 outage가 아니라 이 특정 쿼리 문제임을 확인:

service:cupixworks-api status:error

시간 범위 2026-07-01T07:55:00Z ~ 2026-07-01T08:05:00Z → Found 0 logs

Status board (svc:cupixworks-api::unknown): active 인시던트 없음, 2026-07-01-svc-cupixworks-api--unknown-1은 07-01 01:43~02:02 UTC에 이미 resolved. 이 지연은 별개 이벤트다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 조치 없음(P1 아님). 단발성 200 응답이며 서비스 에러 없음. 다만 admin 사용자가 event 수가 많은 facility를 조회할 때 재현 가능한 UX 저하이므로 아래 단기 개선을 권장.

단기 개선 (1주 이내)#

• events 테이블에 복합 인덱스 추가: (facility_id, eventable_type, created_at DESC) 또는 최소 (facility_id, created_at). 대상 파일: db/migrate/ 신규 마이그레이션. 근거: feed_repository.rb:169-177 쿼리 shape가 facility_id + eventable_type IN (...) filter + created_at DESC sort + LIMIT 이며, 현 인덱스는 filter만 커버하고 sort는 filesort로 처리됨 (db/schema.rb:1931-1939).
• paginate의 COUNT를 줄이기 위해 admin 경로에서 total_entries 필요성을 재검토. 필요 없으면 paginate(..., total_entries: nil) 또는 페이지네이션 방식을 offset → keyset(cursor)로 전환하여 대용량 facility에서도 stable latency 확보.
• Ruby side: event.event_objects.first가 eager_load(:event_objects) 결과에서 in-memory로 첫 element를 선택하도록 보장돼 있는지 확인 (feed_repository.rb:37-42). .first는 has_many 로딩 상태에 따라 재쿼리를 유발할 수 있음 — event.event_objects.to_a.first 또는 event.event_objects.loaded? ? event.event_objects[0] : ... 형태 검토.

장기 개선 (재발 방지)#

• Admin path가 왜 ES를 쓰지 않고 MySQL로 fallback하는지 재검토: _search 경로는 이미 event.team.id/event.user.id 필터로 admin-team 콘텐츠를 제외하며, admin 전용 요구사항(모든 팀 event 조회)이 확실하다면 별도 ES alias + 전용 admin index 를 두는 편이 대량 facility에서도 sub-second를 유지한다.
• APM에서 Api::V1::FeedsController#index p95 SLO 및 db time budget 정의. facility별 event 수 폭증(예: 자동 create) 상황 감시.
• FEED_EVENTABLE_MODEL polymorphic type 확장 시 성능 리뷰 필수. eventable_type cardinality가 낮아 IN 필터의 인덱스 선택성이 약함을 감안한 설계.

Monitoring#

Datadog dashboard (release timeseries widget) 용 쿼리 — writing-datadog-monitoring-queries skill 규칙 준수 (monitor 전용 문법 미사용):

Feed index p95 latency:

p95:trace.rails.request.duration{service:cupixworks-api,resource_name:Api::V1::FeedsController#index}

Feed index high-latency 요청 rate (>5s):

sum:trace.rails.request.hits{service:cupixworks-api,resource_name:Api::V1::FeedsController#index,duration:>5000000000}.as_count()

Feed index DB time contribution:

avg:trace.rails.request.duration{service:cupixworks-api,resource_name:Api::V1::FeedsController#index}

Events 테이블 쿼리 시간 (postgresql 대신 mysql source가 있으면 해당 metric 사용):

avg:mysql.performance.query_run_time_avg{service:cupixworks-api}

Risk Assessment#

• Risk level: low (에러 아님, 200 성공. 단일 발생. UX 영향은 admin 사용자에게 국한)
• 예상 복합도: standard (인덱스 추가 마이그레이션 + 재현/벤치. 대용량 events 테이블에 인덱스 추가 시 online DDL 여부 확인 필요)