RCA: ElementTracesController#index Latency (avg 1282ms, max 1934ms)

Overview#

What Happened#

2026-05-26 03:21~06:09 UTC 동안 Api::V1::ElementTracesController#index 엔드포인트에서 평균 1282ms, 최대 1934ms의 응답 지연이 4개 리전(us-west-2, ap-southeast-1, ap-northeast-1, ap-southeast-2)에 걸쳐 46건 발생했다. DB 처리 시간은 평균 14ms(전체의 1.5%)에 불과하며, 나머지 98.5%의 지연은 application layer에서 발생한다.

Quick Facts#

Timeline#

1. 2026-05-26T03:21:20Z — 최초 slow request 감지 (ap-southeast-2)
2. 2026-05-26T06:09:01Z — 마지막 slow request 기록
3. 2026-05-26 — RCA 분석 완료

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementTracesController#index",
  "service": "cupixworks-api",
  "occurrences": 46,
  "avg_ms": 1282,
  "max_ms": 1934,
  "sample_trace_id": "2420665675104782183"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 46
• 최초 발생: 2026-05-26T03:21:20.106Z
• 최근 발생: 2026-05-26T06:09:01.263Z

Root Cause Summary#

ElementTracesController#index의 latency는 serialization 단계에서 각 ElementTrace 레코드의 association을 Redis cache로 개별 조회하는 fetch_cache 패턴에 기인한다. per_page=300과 14개 필드 조합 시 레코드당 최대 9회의 Redis roundtrip이 발생하여 최대 2700회의 cache lookup이 수행된다. default_joins는 :element, :task만 eager loading하므로 나머지 7개 association(category, phase, workarea, vendor, status, estimated_status, sitetrack)은 모두 Redis fetch_cache fallback을 거친다. Cache miss 시에는 개별 DB query(find_by_id)까지 실행되어 latency가 급증한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/element_traces_controller.rb:11
• ES search: app/repositories/element_trace_repository.rb:198-307
• Permission/Joins: app/repositories/base_repository.rb:70-81
• Serialization: app/serializers/element_trace_serializer.rb:22-53
• Cache fetch: app/models/application_record.rb:84-94
• Cache implementation: app/models/concerns/cachable.rb:58-70

1. Controller가 repository_instance.search(query_option)을 호출한다:

def index
  element_trace_query_option = Cupix::QueryOption::ElementTrace.new(get_query_option, params)
  element_traces = repository_instance.search(element_trace_query_option)

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

2. _search가 Elasticsearch에 쿼리를 실행하고, default_joins가 :element, :task만 eager load한다:

def self.default_joins(record)
  record.includes(:element, :task).select('element_traces.*')
end

3. _skip_join?이 ElementTrace에 대해 true를 반환하여 permission SQL join은 skip된다:

def _skip_join?
  return false if search_public_accessed?

  [::Pano, ::Element, ::ElementTrace, ::Bookmark].include?(self.class.current_class) ||
    search_own_model?
end

4. ApplicationRecord에서 belongs_to 선언 시 자동으로 _#{name} 메서드가 정의된다. 이 메서드가 fetch_cache를 호출하여 Redis에서 관련 모델의 serialized JSON을 조회한다:

class << self
  def belongs_to(name, scope = nil, **options)
    super

    define_method "_#{name}" do |*args, **kwargs, &block|
      if options[:polymorphic]
        fetch_cache(send("#{name}_type"), send("#{name}_id")).merge({
          type: send("#{name}_type")
        }) rescue nil
      else
        model_name = options[:class_name] || name
        model_id = options[:foreign_key] || "#{name}_id"
        fetch_cache(model_name.to_s.classify, send(model_id))
      end
    end
  end
end

5. fetch_cache는 Redis에서 cache key를 조회하고, miss 시 find_by_id + serialized_json을 실행한다:

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

6. Serializer에서 14개 필드 요청 시 _record, _category, _phase, _workarea, _vendor, _status, _estimated_status, _sitetrack 등이 각각 독립적인 Redis roundtrip을 발생시킨다:

attribute :record, &:_record
attribute :deviation, &:_deviation
attribute :sitetrack, &:_sitetrack
attribute :element do |element_trace, params|
  if params[:element_eager_load]
    element = element_trace.element  # eager loaded - no extra query
    # ...
  end
end
attribute :task, &:_task
attribute :category, &:_category
attribute :phase, &:_phase
attribute :workarea, &:_workarea
attribute :vendor, &:_vendor
attribute :status, &:_status
attribute :estimated_status, &:_estimated_status

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api "ElementTracesController" "index" @duration:>500

핵심 로그 패턴 (100건의 slow request에서 추출):

{
  "resource_name": "Api::V1::ElementTracesController#index",
  "duration_ms": 1548,
  "db_time_ms": 11,
  "view_time_ms": 0.05,
  "region": "ap-southeast-2",
  "params": {
    "fields": ["id","record","element","task","category","workarea","phase","vendor","status","estimated_status","processing_result","created_at","updated_at","sitetrack"],
    "per_page": 300,
    "page": 1,
    "facility_key": "5io96"
  }
}

대조 로그 (빠른 요청):

{
  "resource_name": "Api::V1::ElementTracesController#index",
  "duration_ms": 42,
  "params": {
    "fields": ["id","record","element","phase","task"],
    "per_page": 300
  }
}

핵심 수치 비교:

또한 total_entries=0인 요청도 최대 1377ms가 소요된 사례가 있으며, 이는 ES 쿼리 자체의 복잡도(nested bool with cycle_state, trashed_at, purged_at 필터)로 인한 지연도 병존함을 시사한다.

리전별 분포:

ap-southeast-2: 48건, avg 950ms, max 1548ms
ap-southeast-1: 14건, avg 1187ms, max 1802ms
us-west-2: 38건, avg 715ms, max 1526ms

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/element_trace_repository.rb:36-37 — default_joins에 자주 요청되는 association을 추가하여 batch eager loading 처리:
  • 현재: includes(:element, :task)
  • 개선 방향: includes(:element, :task, :category, :phase, :workarea, :vendor, :status, :estimated_status, :sitetrack, :record) 추가 후, serializer에서 eager loaded association을 직접 사용하도록 변경
• app/serializers/element_trace_serializer.rb — _record, _category 등 cache-based accessor 대신 eager loaded association을 직접 참조하도록 serializer 로직을 변경하는 것이 근본 해결

단기 개선 (1주 이내)#

• Batch cache fetch 도입: 현재 레코드별 개별 Rails.cache.fetch를 Rails.cache.read_multi로 교체하여 Redis roundtrip을 N×M에서 1회로 줄이는 방식 검토
• Serializer 분기 최적화: element_eager_load: true 패턴을 category, phase, workarea 등에도 확장하여 eager loaded 객체를 직접 serialization

장기 개선 (재발 방지)#

• ApplicationRecord.belongs_to의 _#{name} 자동 생성 패턴을 재검토. 컬렉션 API에서 per-record cache fetch는 구조적으로 latency를 유발하므로, 컬렉션 조회 시에는 eager loading 기반 serialization을 기본으로 사용하는 아키텍처 전환 필요
• Elasticsearch query의 cycle_state_filter 복잡도 감소 (nested bool 단순화) 검토

Monitoring#

• 추가 메트릭: ElementTracesController#index p95 duration에 대한 monitor 설정
• Datadog 쿼리:

service:cupixworks-api resource_name:"Api::V1::ElementTracesController#index" @duration:>1000

• Redis cache hit rate 모니터링: Cache::Category::*, Cache::Phase::*, Cache::Workarea::* key 패턴의 hit/miss ratio 추적

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — eager loading 추가는 기존 패턴과 일관되나, serializer 변경은 다른 endpoint에도 영향을 줄 수 있어 regression 테스트 필요