Api::V1::PhasesController#index (avg 5017ms, max 5017ms)

RCA: Api::V1::PhasesController#index Slow Response (5017ms)

Overview#

What Happened#

2026-06-04 07:15 KST에 cupixworks-api 서비스의 Api::V1::PhasesController#index 엔드포인트가 5017ms 응답 시간을 기록했다. 동일 시간대에 대량 Pano 업로드로 인한 시스템 전반 부하가 발생하여, serialization 병목과 connection pool 경합이 복합적으로 작용한 latency 인시던트이다.

Quick Facts#

Field	Value
resource_name	`Api::V1::PhasesController#index`
duration	`5017ms` (DB: 432ms, Serialization: 1942ms, Unaccounted: 2624ms)
top_frame	`app/repositories/phase_repository.rb:190`
env	production, us-west-2
facility_key	`dwwuda`
total_entries	33

Timeline#

2026-06-04 07:15 KST — PhasesController#index 요청 시작 (facility_key=dwwuda, user: olivia.terry@clarkconstruction.com)
2026-06-04 07:15 KST — 동일 호스트에서 30+ 동시 slow request 발생 (PanosController bulk upload)
2026-06-04 07:15 KST — 요청 완료 (5017ms, HTTP 200)
2026-06-04 07:20 KST — 동일 facility 재요청 시 235ms로 정상 응답 (부하 해소 후)

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::PhasesController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 5017,
  "max_ms": 5017,
  "sample_trace_id": "1235968599694469352"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-06-04 07:15 KST
최근 발생: 2026-06-04 07:15 KST

Root Cause Summary#

PhasesController#index의 slow response는 두 가지 요인의 복합 작용으로 발생했다. 첫째, PhaseSerializer가 _texture, _category, _workarea_group, _trade, _user 등 5개 이상의 belongs_to 연관 데이터를 개별적으로 fetch_cache → find_by_id로 조회하는데, cache miss 시 N+1 쿼리가 발생하여 33개 레코드에서 serialization만 1942ms가 소요되었다. 둘째, 동일 시간대 대량 Pano 업로드(30+ 동시 요청)로 인한 connection pool 경합과 GC 압박이 약 2624ms의 추가 대기 시간을 유발했다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/phases_controller.rb — index action
Repository 호출: app/repositories/phase_repository.rb:190 — search 메서드
DB 조회: Phase.untrashed.where(facility_id:).order(row_order: :asc).paginate(...) 실행
Join 적용: default_joins — .joins(:team).select('phases.*') (team만 join, 다른 association 미포함)
Serialization: PhaseSerializer — 각 phase 레코드마다 _texture, _category, _workarea_group, _trade, _user 호출
Cache lookup: app/models/concerns/cachable.rb:58 — fetch_cache 메서드에서 cache miss 시 find_by_id 개별 쿼리 실행

app/controllers/api/v1/phases_controller.rb:indexruby

def index
  phase_query_option = Cupix::QueryOption::Phase.new(get_query_option, params)
  phases = repository_instance.search(phase_query_option)

  render_api Renderable.new({
    search_result: phases,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

app/repositories/phase_repository.rb:190-224ruby

def search(query_option = nil)
  set_query_option(query_option)

  query = ::Phase.untrashed

  if self.query_option.facility_key.present?
    facility = FacilityRepository.new(current_user: self.current_user).show(self.query_option.facility_key)
    query = query.where(facility_id: facility.id)
  end

  phases = query.order(row_order: :asc).paginate(
    per_page: self.query_option.per_page,
    page: self.query_option.page
  )

  SearchResult.new(
    contents: self.class.default_joins(phases),  # team만 join
    pagination: { ... }
  )
end

app/repositories/phase_repository.rb:36-38ruby

def self.default_joins(record)
  record.joins(:team).select('phases.*')
end

app/serializers/phase_serializer.rb:1-34ruby

class PhaseSerializer
  include CupixSerializer

  attribute :id
  attribute :name
  attribute :user, &:_user
  attribute :texture, &:_texture
  attribute :category, &:_category
  attribute :workarea_group, &:_workarea_group
  attribute :trade, &:_trade
  # ... 각 attribute 접근 시 fetch_cache 호출
end

app/models/concerns/cachable.rb:58-70ruby

def fetch_cache(model_name = self.class.name, model_id = self.id)
  return nil if model_id.blank?

  Rails.cache.fetch(cache_key(model_name, model_id), skip_nil: true, expires_in: self.class.cache_expires_in) do
    if self.respond_to?("serialized_#{model_name.underscore}_json".to_sym)
      self.send("serialized_#{model_name.underscore}_json")
    else
      record = model_name.constantize.find_by_id(model_id)  # Cache miss → 개별 DB 쿼리
      record.serialized_json if record.respond_to?(:serialized_json)
    end
  end
end

기대 동작: 33개 phase 레코드 조회 + 직렬화가 200-300ms 이내 완료 실제 동작: DB 432ms + Serialization 1942ms + Unaccounted 2624ms = 약 5000ms. Cache miss가 발생하면 33 × 5 associations = 최대 165개 개별 쿼리가 실행되며, 동시 부하로 connection pool 대기까지 가중됨.

Log Evidence#

Datadog에서 확인한 동일 시간대 요청 비교:

text

Query: service:cupixworks-api (PhasesController OR phases)
Time: 2026-06-03T21:15:00Z to 2026-06-03T23:00:00Z

동일 facility_key=dwwuda, 동일 사용자의 응답 시간 비교:

text

22:15:22 UTC — 4999ms (DB: 432ms, Serialization: 1942ms) ← 인시던트 시점
22:20:57 UTC — 235ms  (DB: 119ms, Serialization: 111ms)  ← 5분 후 정상

더 많은 레코드(62개)를 가진 다른 facility에서도 유사 패턴:

text

21:58:25 UTC — 5808ms (DB: 722ms, Serialization: 4447ms, 62 entries, facility: 3fq7tj)

동일 시간대 시스템 부하 확인:

text

Query: service:cupixworks-api @duration:>3000
Time: 2026-06-03T22:14:00Z to 2026-06-03T22:16:00Z
Results: 30 slow requests (PanosController#create: 6-12s, PanosController#check_uploading: 3-7s)

인시던트 시점의 상세 로그:

json

{
  "controller": "Api::V1::PhasesController#index",
  "duration": 4999.55,
  "db_runtime": 432.8,
  "serialization_runtime": 1942,
  "view_runtime": 0.11,
  "total_entries": 33,
  "per_page": 100,
  "page": 1,
  "params": { "facility_key": "dwwuda", "fields": ["id", "name", "workflow", "texture", "category", "trade", "row_order"] },
  "user": "olivia.terry@clarkconstruction.com",
  "host": "ip-10-1-19-190.us-west-2.compute.internal",
  "request_id": "5cdf064d-bcb4-420d-9ef4-b1aff1ef0f99"
}

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Serialization N+1 쿼리: cache miss 시 belongs_to 연관 데이터를 개별 조회하여 병목 발생	Serialization 1942ms (전체의 39%). `default_joins`는 team만 join, 나머지 5개 association은 `fetch_cache` → `find_by_id` 개별 호출. 62개 레코드 facility에서는 serialization만 4447ms.	Cache hit 시에는 빠름 (22:20:57에 동일 facility 111ms serialization)	Confirmed
H2	Connection pool 경합: 동시 대량 요청으로 DB connection 대기 발생	동일 시간대 30+ slow requests 동시 실행. Unaccounted time 2624ms. 5분 후 동일 요청은 정상 응답.	명시적 connection pool timeout 에러 로그 없음	Confirmed (contributing)
H3	DB 쿼리 자체의 성능 문제 (인덱스 미사용, 대용량 테이블 scan)	DB time 432ms로 평소(119ms) 대비 3.6배 상승	인시던트 후 동일 쿼리 정상 (119ms). Slow query 로그 없음. 테이블 구조상 facility_id 인덱스 존재 추정	Rejected (일시적 부하 영향)
H4	GC(Garbage Collection) pause로 인한 지연	Unaccounted time 2624ms가 DB/serialization 외 시간. 30+ 동시 요청에 의한 메모리 압박 환경	GC 로그 직접 확인 불가	Inconclusive

Fix Recommendation#

즉시 조치 (Critical)#

app/repositories/phase_repository.rb:220 — default_joins 대신 includes를 추가하여 serializer가 사용하는 연관 데이터를 eager load:
- includes(:texture, :category, :workarea_group, :trade, :user, :team)
또는 SearchResult 생성 시 contents에 eager load된 결과를 전달하도록 수정

단기 개선 (1주 이내)#

PhaseSerializer의 fields 파라미터를 활용하여 요청된 필드의 연관 데이터만 선택적으로 eager load하는 로직 추가. 예: fields에 texture가 없으면 :texture includes 제외.
fetch_cache 메커니즘이 batch preload와 호환되도록 개선 검토 — 현재 개별 find_by_id는 eager loading의 이점을 무효화할 수 있으므로, eager loaded된 association이 있으면 cache 대신 직접 사용하도록 분기 처리

장기 개선 (재발 방지)#

API 서버의 connection pool 모니터링 및 pool size 확장 검토 (동시 대량 요청 시 경합 완화)
대량 Pano 업로드 작업을 별도 worker/queue로 분리하여 API 서버 리소스 경합 방지
Serialization 레이어에 대한 APM 계측 강화 — 개별 association 조회 시간 추적

Monitoring#

Phase index 응답 시간 p95/p99 모니터링:

text

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::phasescontroller#index} by {host}

Serialization 시간 비율 알림 (serialization > 1000ms):

text

service:cupixworks-api resource_name:"Api::V1::PhasesController#index" @serialization_runtime:>1000

Connection pool 사용률 모니터:

text

avg:ruby.active_record.pool.size{service:cupixworks-api} - avg:ruby.active_record.pool.available{service:cupixworks-api}

Risk Assessment#

Risk level: medium
예상 복잡도: standard — eager loading 추가는 비교적 간단하나, fetch_cache 메커니즘과의 호환성 확인 필요