RCA: Api::V1::AssetsController#index 응답 지연 (avg 20s, max 20s)

Overview#

What Happened#

2026-06-25 00:05 ~ 02:44 KST 사이, cupixworks-api 의 Api::V1::AssetsController#index 엔드포인트가 평균 15s, 최대 20s 응답시간으로 동작했다. Datadog request 로그를 추가 조회한 결과 동일 시간대에 같은 엔드포인트 / 같은 사용자에 대해 27.7s ~ 59.0s 까지 늘어난 요청이 다수 관찰되었으며, 전체 응답 시간의 >95% 가 serializer 단계에 집중되어 있었다 (예: total 59,074ms 중 serialization.duration = 56,128ms). 모든 slow request 는 단일 review (review_key=vml3bc, Enbridge 테넌트, team_id=1088)에서 동일 사용자(iyang@hycrofteng.com)가 per_page=100 으로 page 26~38 까지 순차 페이지네이션 한 흐름에서 발생했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-25 00:05 KST — Api::V1::AssetsController#index 첫 slow 요청 (cluster first_seen)
2. 2026-06-25 02:37 KST — Enbridge 사용자가 review_key=vml3bc 에 대해 page 단위 페이지네이션 시작 (per_page=100)
3. 2026-06-25 02:44 KST — page 30 요청 응답 59,074ms (serialization 56,128ms) — cluster last_seen
4. 2026-06-25 02:44 KST — page 31 요청 응답 27,700ms (serialization 25,134ms)
5. 2026-06-25 02:47 KST — page 38 요청 응답 15,081ms

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::AssetsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 20050,
  "max_ms": 20050,
  "sample_trace_id": "4262490745666060882"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2 (cluster) + 같은 시간대 동일 패턴의 slow request 5건 이상 추가 관측
• 최초 발생: 2026-06-25 00:05 KST
• 최근 발생: 2026-06-25 02:44 KST

Root Cause Summary#

AssetSerializer 가 child_assets, badges, annotations, cover_urls, thumbnail_urls 필드를 모두 expand 하도록 요청받은 상태에서 per_page=100 페이지네이션이 적용되면, 페이지 1건당 serializer 가 asset 1개 × 5개 무거운 attribute 단위로 N+1 패턴(asset.parent_asset&.key 호출, _associated_badges / _associated_annotations 의 Rails.cache.fetch miss 시 DB 2회 조회, cover_urls 의 S3 presigned URL 생성 등)을 반복 실행한다. 이로 인해 100개 asset 직렬화에 2556초가 소요되어 사용자가 review 페이지를 넘길 때 전체 응답이 1559초까지 늘어났다. 외부 의존성(Elasticsearch, S3) 자체 장애가 아니라, serializer 의 per-asset 비용이 페이지 크기와 곱해진 결과라는 점이 핵심이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/assets_controller.rb:15-25
• Search 단계 (Elasticsearch): app/repositories/asset_repository.rb:225-300
• Permission join 후 ActiveRecord 결과 반환: app/repositories/base_repository.rb:70-112
• Serializer per-asset expansion (failure point): app/serializers/asset_serializer.rb:58-97

def index
  assets = repository_instance.search(
    Cupix::QueryOption::Asset.new(get_query_option, params)
  )

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

per_page=100 으로 호출된 search 자체는 Elasticsearch + permission JOIN 으로 구성되며 응답 로그상 view/db 시점은 빠르다 (view: 0.09~0.13). 병목은 render_api 이후 serializer 단계에 있다.

attribute :child_assets do |model|
  model.child_assets.map do |asset|
    {
      id: asset.id,
      key: asset.key,
      parent_asset_key: asset.parent_asset&.key,   # asset 단위 belongs_to 재조회 (N+1)
      ...
      cover_urls: asset.cover_urls,                # cover_state_uploaded? 분기 시 S3 presigned URL 생성
      thumbnail_urls: asset.thumbnail_urls,
      ...
    }
  end
end

attribute :badges do |asset|
  if asset._associated_badges[:associated_resourcable_ids].present?
    asset._associated_badges[:associated_resourcable_ids].map { |id| { id: id } }
  else
    []
  end
end

attribute :annotations do |asset|
  if asset._associated_annotations[:associatable_ids].present?
    asset._associated_annotations[:associatable_ids].map { |id| { id: id } }
  else
    []
  end
end

_associated_badges / _associated_annotations 는 Rails.cache.fetch 로 감싸져 있으나, cache miss 시 asset 1건당 Association.where(...).first 를 최대 2회 실행한다.

def fetch_association_cache(source_model_name, source_model_id, related_model_name)
  cache_key = association_cache_keys(source_model_name, source_model_id, related_model_name).first

  Rails.cache.fetch(cache_key, skip_nil: true, expires_in: self.class.cache_expires_in) do
    association_by_associatable = ::Association.where(associatable_type: source_model_name, associatable_id: source_model_id, associated_resourcable_type: related_model_name).first
    association_by_resourcable = nil

    if association_by_associatable.nil?
      association_by_resourcable = ::Association.where(associatable_type: related_model_name, associated_resourcable_type: source_model_name, associated_resourcable_id: source_model_id).first
    end
    ...
  end
end

기본 includes 는 child_assets, storage 만 포함하므로 serializer 가 추가로 접근하는 parent_asset, Association (badges/annotations) 은 eager-load 되지 않는다.

def self.default_joins(record)
  record.includes(:child_assets, :storage).joins("
    LEFT JOIN workspaces ON workspaces.id = assets.workspace_id
    LEFT JOIN users ON users.id = assets.user_id
    ...
  ").select('
    assets.*,
    workspaces.name AS workspace_name,
    ...
  ')
end

기대 동작은 페이지당 단일 자릿수 초 이내 응답이지만, 실제로는 100개 asset 각각이 5개 무거운 attribute 와 N+1 조회를 반복하면서 serializer 단계만으로 25~56s 가 소비되었다.

Log Evidence#

Datadog 쿼리 (재현용):

service:cupixworks-api "AssetsController#index"
2026-06-24T17:30:00Z ~ 2026-06-24T17:50:00Z

같은 시간대 / 같은 review (vml3bc) / 같은 사용자 page 30 요청 — total 59,074ms 중 serialization 56,128ms:

{
  "@timestamp": "2026-06-24T17:44:35.292Z",
  "controller": "Api::V1::AssetsController",
  "action": "index",
  "duration": 59074.69,
  "view": 0.1,
  "serialization": { "duration": 56128 },
  "http": { "status_code": 200, "method": "GET", "url_details": { "path": "/api/v1/reviews/vml3bc/assets" } },
  "team": { "domain": "enbridge", "id": 1088 },
  "user": { "id": 49816, "email": "iyang@hycrofteng.com" },
  "params": {
    "per_page": "100",
    "review_key": "vml3bc",
    "page": "30",
    "fields": ["key","name","description","summary","user","facility","review",
               "created_at","updated_at","asset_type","assetable",
               "cover_urls","thumbnail_urls","state","cover_state",
               "transcript_state","meta","badges","annotations",
               "child_assets","storage"]
  }
}

같은 사용자 page 31 (직후 요청) — total 27,700ms / serialization 25,134ms:

{
  "controller": "Api::V1::AssetsController",
  "action": "index",
  "duration": 27700.74,
  "view": 0.12,
  "serialization": { "duration": 25134 },
  "params": { "per_page": "100", "review_key": "vml3bc", "page": "31", "fields": [/* 동일 23 fields */] },
  "team": { "domain": "enbridge", "id": 1088 }
}

같은 시간대 동일 엔드포인트 top duration 분포 (검색 결과에서 추출):

duration(ms): 1706.81, 1743.94, 2108.86, 2417.24, 3098.87, 4771.52,
              15081.83, 27700.74, 49331.16, 59074.69

view (DB/렌더링 view 단계) 는 모두 0.1초 미만이며, 상위 4건 모두 serialization.duration 이 total 의 90% 이상을 차지했다. cupixworks-api status:error 로그는 같은 윈도에서 BIM360 / OPC 인증 관련 무관 에러 4건뿐이며 Elasticsearch circuit breaker (SYS20000) 나 Bad Gateway (BG10002) 는 발생하지 않았다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 즉시 운영 측 mitigation: client (web/Enbridge 사용자 흐름)에서 review asset 페이지네이션 시 per_page 를 50 이하로 낮추거나, child_assets / badges / annotations 중 화면에 즉시 필요하지 않은 필드를 fields 파라미터에서 제거하는 것을 권장. app/controllers/api/v1/assets_controller.rb:15 변경 없이 호출 측 옵션만 조정해도 latency 가 선형으로 감소한다 (관측: per_page=100 → 25~56s, view 단계 비례 감소 예상).

단기 개선 (1주 이내)#

• app/serializers/asset_serializer.rb:58-77 child_assets attribute: model.child_assets.map { ... asset.parent_asset&.key ... } 의 parent_asset&.key 는 child 가 다시 자신의 parent 를 참조하는 self-join 패턴이므로, repository 단계에서 child_assets 컬렉션에 대해 parent_asset 을 함께 preload (includes(child_assets: :parent_asset)) 하도록 AssetRepository.default_joins (app/repositories/asset_repository.rb:55-71) 수정 검토. 단, 셀프 참조가 무한 재귀를 만들지 않도록 단일 hop 으로 제한.
• app/serializers/asset_serializer.rb:79-97 badges / annotations: _associated_badges / _associated_annotations 는 cache miss 시 per-asset DB 조회를 일으키므로, 100개 asset 묶음에 대해 한 번에 Association.where(associatable_type: 'Asset', associatable_id: ids, ...) 로 prefetch 하여 in-memory map 으로 lookup 하는 batch loader 도입 검토. ResourcableAttribute / CoverAttribute 등 다른 mixin 도 같은 패턴이면 동일하게 검토.
• 컨트롤러에서 per_page 상한 (예: 50)을 강제하거나, child_assets 같은 무거운 필드가 요청되었을 때 자동으로 상한을 더 낮추는 가드를 Api::V1::ApiController 레벨에 추가.

장기 개선 (재발 방지)#

• serializer 단계에 대한 가시성 강화: serialization.duration 은 이미 로그에 있으므로 Datadog APM custom span 으로 승격하여 attribute 별 (child_assets, badges, ...) 시간 분해가 가능하도록 instrumentation.
• review 단위 자산 목록은 사용자가 마지막 page 까지 sequential 하게 넘기는 워크플로가 자주 발생하므로, 무한 스크롤/cursor 기반 페이지네이션 또는 가벼운 list view (fields=key,name,thumbnail_urls,state 만) 를 default 로 두고 detail 은 row click 시 lazy load 하는 UX 분리 검토.
• per-asset Association cache miss 시 N+1 비용을 구조적으로 막기 위해, Asset 검색 결과 hydration 단계에서 badges/annotations 를 일괄 preload 하는 repository helper 도입.

Monitoring#

• Datadog APM: Api::V1::AssetsController#index p95 / p99 latency 모니터링.
• request 로그 serialization.duration 추적 (timeseries widget): 요청 총 시간 대비 serialization 비중이 50% 를 넘는 비율 trend.

service:cupixworks-api @controller:Api::V1::AssetsController @action:index @duration:>5000

service:cupixworks-api @controller:Api::V1::AssetsController @action:index @serialization.duration:>3000

service:cupixworks-api @controller:Api::V1::AssetsController @action:index @params.per_page:>=100

@params.fields:child_assets, @params.fields:badges, @params.fields:annotations 로 무거운 필드 요청 빈도 dashboard 화도 권장.

Risk Assessment#

• Risk level: medium — 단일 review / 단일 테넌트의 sequential pagination 에 국한된 패턴이지만, per-asset N+1 자체는 같은 코드 경로를 쓰는 다른 테넌트/리뷰에서도 데이터 규모가 커지면 동일하게 재현될 수 있다. 외부 dep 장애가 아니므로 자연 회복은 기대하기 어렵다.
• 예상 복잡도: standard — 즉시 조치(요청 옵션 조정)는 trivial, 단기 개선(child_assets+parent_asset preload, badges/annotations batch loader)은 serializer/repository 양쪽 변경이 필요하나 기존 default_joins / Cachable 패턴 안에서 가능.