RCA: Api::V1::VideosController#index Latency (avg 1039ms, max 1057ms)

Overview#

What Happened#

2026-05-26 05:52~06:04 UTC 사이에 cupixworks-api 서비스의 Api::V1::VideosController#index 엔드포인트에서 평균 1039ms, 최대 1057ms의 높은 응답 지연이 발생했다. ap-southeast-2와 us-west-2 리전에서 cupix-agent 클라이언트의 요청에서만 관측되었으며, 결과 세트는 1-2건으로 매우 작았음에도 불구하고 높은 지연이 발생했다.

Quick Facts#

Timeline#

1. 2026-05-26T05:52:22Z — 최초 고지연 요청 감지 (us-west-2, 1055ms)
2. 2026-05-26T06:04:50Z — 마지막 고지연 요청 (ap-southeast-2, 1019ms)
3. 2026-05-26T06:09:24Z — 추가 고지연 요청 지속 관측 (860ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::VideosController#index",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 1039,
  "max_ms": 1057,
  "sample_trace_id": "3844722111894990690"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2 (>1000ms threshold 초과), 추가 11건이 >500ms
• 최초 발생: 2026-05-26T05:52:22.577Z
• 최근 발생: 2026-05-26T06:04:50.276Z
• 영향 범위: cupix-agent 내부 서비스 호출 (graymont, built, pace 팀의 capture 조회)

Root Cause Summary#

VideosController#index 요청의 높은 지연은 serialization 레이어의 sequential cache lookup에 기인한다. Datadog APM 로그에서 DB 시간이 10-33ms에 불과하지만 전체 응답 시간은 500-1057ms로, ~97%의 시간이 application 레이어에서 소비된다. VideoSerializer에서 각 video에 대해 _facility, _user, _workspace, _team 속성을 직렬화할 때 fetch_cache() 메서드가 순차적으로 Redis를 조회하고, cache miss 시 find_by_id() DB 호출로 fallback하는 구조가 주요 원인이다. 또한 _search() 메서드에서 CaptureRepository.new(...).show(capture_id) 호출이 추가 DB + permission 체크를 수행하여 기본 latency를 증가시킨다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/videos_controller.rb:10
• _search() 호출 (Elasticsearch + Capture lookup): app/repositories/video_repository.rb:345
• BaseRepository#search() — ES 결과에 joins 적용: app/repositories/base_repository.rb:70
• default_joins() — 11개 LEFT JOIN: app/repositories/video_repository.rb:27
• permission_joins() — 12개 중첩 LEFT JOIN + GROUP BY: app/repositories/video_repository.rb:59
• Serialization — sequential cache lookups: app/serializers/video_serializer.rb:9-13
• fetch_cache() — Redis 조회 + find_by_id fallback: app/models/concerns/cachable.rb:58-70

1. Controller → Repository 호출

def index
  video_query_option = Cupix::QueryOption::Video.new(get_query_option(enable_current_team: false), params)
  videos = repository_instance.search(video_query_option)

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

2. _search()에서 CaptureRepository#show 호출 — 추가 DB + 권한 체크

def _search(query_option = {})
  set_query_option(query_option)

  if self.query_option.capture_id.blank?
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'capture_id is required')
  end

  capture = CaptureRepository.new(current_user: self.current_user).show(self.query_option.capture_id)

  self.query_option.query[:bool][:must] << {
    term: { "capture.id": capture.id }
  }

  response = ::Video.search(
    self.query_option.serializable_hash
  ).paginate(
    per_page: self.query_option.per_page,
    page: self.query_option.page
  )

  set_response(response)
end

CaptureRepository#show는 단순 ID lookup이 아니라 permission 검증을 포함하는 repository 패턴이므로, 이 단계에서 이미 추가 DB + permission join이 발생한다.

3. BaseRepository#search — ES 결과에 default_joins + permission_joins 적용

def search(query_option = nil)
  _search(query_option)

  begin
    if self.review.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review.id, skip_join: _skip_join?)
    elsif self.capture.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, capture_id: self.capture.id, skip_join: _skip_join?)
    else
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end

ES에서 반환된 1-2건의 레코드 ID에 대해 23개 LEFT JOIN + GROUP BY + GREATEST/IFNULL 연산을 수행한다. 결과 세트가 작기 때문에 DB 시간 자체는 10-33ms로 낮지만, 쿼리 생성 및 실행 오버헤드가 존재한다.

4. Serializer의 sequential cache lookups — 핵심 병목

attribute :facility, &:_facility
attribute :user, &:_user
attribute :workspace, &:_workspace
attribute :team, &:_team

각 _facility, _user 등은 Cachable#fetch_cache()를 호출한다:

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)
      record.serialized_json if record.respond_to?(:serialized_json)
    end
  end
end

video 1건당 최소 4회의 Rails.cache.fetch() 호출이 순차적으로 실행된다. Redis RTT가 ap-southeast-2에서 2-5ms라면, 캐시 히트만으로도 video 2건 × 4 attributes = 16-40ms가 소요된다. Cache miss 시 각 호출이 find_by_id() + serialized_json을 수행하므로, 1건당 10-50ms 추가 지연이 발생한다.

5. cupix-agent 요청의 특수성

Datadog 로그에서 확인된 고지연 요청의 공통점:

• User-Agent: cupix-agent (내부 서비스 호출)
• per_page: 100, fields: 10개 필드 요청
• 동일 시간대 Python/3.10 aiohttp 클라이언트는 50-100ms로 응답

cupix-agent가 요청하는 10개 필드(id, name, state, pts_unit, capture, facility, meta, created_at, updated_at, captured_at) 중 facility 필드가 _facility cache lookup을 트리거한다. aiohttp 클라이언트는 더 적은 필드를 요청하여 cache lookup을 회피하는 것으로 추정된다.

Log Evidence#

Datadog APM 로그에서 확인된 고지연 요청 패턴:

Query: service:cupixworks-api "VideosController" @duration:>500
Time: 2026-05-26T04:52:00Z ~ 2026-05-26T06:10:00Z

대표 로그 항목:

{
  "timestamp": "2026-05-26T05:52:24.932Z",
  "resource_name": "Api::V1::VideosController#index",
  "duration_ms": 1055.67,
  "db_duration_ms": 10.02,
  "region": "us-west-2",
  "host": "ip-10-1-19-190",
  "team": "graymont",
  "capture_id": 702496,
  "user_agent": "cupix-agent",
  "per_page": 100,
  "total_entries": 1
}

{
  "timestamp": "2026-05-26T06:04:51.858Z",
  "resource_name": "Api::V1::VideosController#index",
  "duration_ms": 1019.84,
  "db_duration_ms": 31.99,
  "region": "ap-southeast-2",
  "host": "ip-10-1-145-251",
  "team": "built",
  "capture_id": 73286,
  "user_agent": "cupix-agent",
  "per_page": 100,
  "total_entries": 2
}

핵심 관측:

• DB 시간: 10-33ms (전체 duration의 ~3%)
• View 시간: <1ms
• Serialization 시간: 3-6ms (Datadog 측정 — fetch_cache() 호출은 여기 포함되지 않음)
• ~97%의 시간이 미측정 application 레이어에서 소비됨

APM 메트릭 확인:

Query: avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::videoscontroller_index}
Result: average ~198ms, spikes to 1003ms (intermittent)

정상 요청 (같은 시간대, aiohttp 클라이언트)은 50-100ms로 응답, cupix-agent 요청만 고지연 — 필드 선택 차이로 인한 serialization 경로 차이 확인.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/serializers/video_serializer.rb:9-13 — _facility, _user, _workspace, _team 호출 시 batch cache fetch 도입. Rails.cache.read_multi()를 사용하여 4개 키를 단일 Redis roundtrip으로 조회하도록 변경.
• app/models/concerns/cachable.rb:58-70 — cache miss 시 find_by_id 호출을 개별이 아닌 batch로 수행하도록 fetch_multi 패턴 도입.

단기 개선 (1주 이내)#

• app/repositories/video_repository.rb:352 — CaptureRepository#show() 대신 단순 Capture.find(capture_id)로 변경하여 불필요한 permission join 제거. 이미 상위에서 인증된 사용자이므로 capture 접근 권한은 video 레벨에서 검증 가능.
• cupix-agent 클라이언트 측에서 facility 필드를 필요한 경우에만 요청하도록 변경 검토 (불필요한 필드 제거 시 _facility cache lookup 회피 가능).

장기 개선 (재발 방지)#

• Serializer의 fetch_cache() 패턴을 preloading 패턴으로 전환: serialization 시작 전에 필요한 모든 관련 모델을 한 번에 로드 (SQL IN 절 사용).
• VideoSerializer에 field-based conditional serialization 강화: 요청된 필드에 따라 불필요한 cache lookup 자체를 건너뛰도록 구현.
• APM instrumentation에서 fetch_cache() 호출을 custom span으로 추적하여 cache hit/miss 비율 및 latency를 가시화.

Monitoring#

• fetch_cache() 호출에 custom metric 추가:

dogstatsd.timing('cache.fetch_cache.duration', elapsed, tags: ['model:Facility', 'hit:true/false'])

• VideosController#index p95 latency 알림:

avg(last_5m):trace.rack.request.duration.by.resource_name.p95{service:cupixworks-api,resource_name:api::v1::videoscontroller_index} > 800

• Cache miss rate 모니터링:

sum:cache.fetch_cache.miss{service:cupixworks-api,model:*}.as_count() / sum:cache.fetch_cache.total{service:cupixworks-api,model:*}.as_count()

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard — fetch_cache의 batch 화는 기존 패턴을 유지하면서 read_multi 도입으로 해결 가능하나, 모든 serializer에 공통 적용되는 Cachable concern 변경이므로 regression 테스트 필요.