RCA: Api::V1::TradeTaskTracesController#index (avg 10654ms, max 10654ms)

Overview#

What Happened#

2026-08-04 02:30:59 KST에 cupixworks-api (us-west-2) 의 Api::V1::TradeTaskTracesController#index 요청 하나가 10,640ms 동안 실행되었다. 반환된 레코드는 72건이었지만 응답 전체 시간의 76% (8,038ms) 가 serializer 단계에서 소비되었고, 동일한 facility/record_id 로 15분 후 반복된 동일 요청은 107ms 로 완료되어 100배 차이가 관측되었다. 자동화된 preprocessor agent (cupix-sitetrack-preprocessor-agent) 가 유일한 caller 로, 콜드 캐시 상태에서 associated model (record, capture, workarea, trade) 별 fetch_cache 미스 캐스케이드가 발생한 것으로 판단된다.

Quick Facts#

Affected Teams#

동일 endpoint 를 사용하는 프론트엔드 caller 는 발견되지 않았고 자동화 agent 요청이 유일한 소스이다.

Timeline#

1. 2026-08-04 02:30:59 KST — GET /api/v1/facilities/kgo4s6/trade_task_traces?record_id=140677&per_page=100&page=1 요청 시작 (trace_id 8735584501938793007).
2. 2026-08-04 02:31:10 KST — 동일 요청 200 응답, duration=10,640ms, serialization=8,038ms.
3. 2026-08-04 02:46:45 KST — 동일 파라미터 재요청 완료, duration=107ms, serialization=54ms (캐시 warm).
4. 2026-08-04 02:59:57 KST — 동일 파라미터 재요청 완료, duration=121ms, serialization=86ms (지속적으로 warm).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::TradeTaskTracesController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10654,
  "max_ms": 10654,
  "sample_trace_id": "8735584501938793007"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (14일 retention 창 내)
• 최초 발생: 2026-08-04 02:30:59 KST
• 최근 발생: 2026-08-04 02:30:59 KST

한 건의 slow request 이지만 자동화 agent 의 반복 호출 특성상 콜드 캐시 시나리오 (deploy 직후 · 캐시 eviction · TTL 만료 · 신규 record 대량 유입) 마다 재현 가능하다.

Root Cause Summary#

TradeTaskTraceSerializer 는 belongs_to association (record, capture, workarea, trade) 각각을 application_record.rb:84 에서 동적 정의한 _#{name} 메서드로 직렬화한다. 이 메서드는 preloaded ActiveRecord association 을 사용하지 않고 대신 fetch_cache(model_name, model_id) 를 호출하여 Rails.cache 에서 개별 캐시 엔트리를 조회한다. 결과 72건 × association 4개 = 288회 fetch_cache 가 순차 실행되며, 캐시 미스 시마다 (1) Rails.cache 왕복 (2) Model.find_by_id DB 조회 (3) 대상 모델의 serialized_json 재귀 생성 (4) Rails.cache.write 가 모두 인라인으로 발생한다. Datadog 로그에서 동일 파라미터의 후속 요청이 100배 빠른 (10,640ms → 107ms) 점, serialization 이 8,038ms 로 db(768ms) 를 크게 상회하는 점이 콜드 캐시 미스 캐스케이드를 뒷받침한다. TradeTaskTraceRepository.default_joins 는 .includes(:record, :capture, :workarea, :trade) 로 eager load 를 수행하지만, serializer 가 preload 를 무시하고 캐시 경로로 우회하므로 eager loading 이 무의미하다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/trade_task_traces_controller.rb:9

def index
  query_option = Cupix::QueryOption::TradeTaskTrace.new(get_query_option, params)
  traces = repository_instance.search(query_option)

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

Repository search 는 최종적으로 default_joins 로 preload 를 붙여 SearchResult 를 만든다:

traces = query.order(analyzed_at: :desc, id: :desc).paginate(
  per_page: self.query_option.per_page,
  page: self.query_option.page
)

SearchResult.new(
  contents: self.class.default_joins(traces),
  pagination: {
    total_entries: traces.total_entries,
    ...
  }
)

def default_joins(record)
  record.includes(:record, :capture, :workarea, :trade)
end

Serializer 는 preload 된 association 대신 _record/_capture/_workarea/_trade 를 호출한다:

attribute :record, &:_record
attribute :capture, &:_capture
attribute :workarea, &:_workarea
attribute :trade, &:_trade

이 helper 는 ApplicationRecord.belongs_to override 에서 동적으로 정의된다:

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

Failure point: app/models/concerns/cachable.rb:58 — 캐시 미스 경로가 인라인 SQL 조회 + 재귀 직렬화를 수행하고 각 association 마다 반복된다.

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

기대 동작: default_joins 의 .includes 로 4개 association 이 한 번의 IN 쿼리로 preload 되어, 72건 직렬화 시 추가 DB 왕복 없이 in-memory 로 처리되어야 한다.

실제 동작: serializer 는 preloaded association 을 사용하지 않고 fetch_cache 로 우회하여 (a) 72×4=288회 Rails.cache 왕복 (b) 미스 시 record 별 find_by_id + serialized_json (c) 각 항목마다 Rails.cache.write 를 수행. Warm 상태에서는 (a) 만 발생해 100ms 수준, 콜드 상태에서는 (b)/(c) 가 288회 반복되어 8초대로 급증.

Log Evidence#

Datadog 로그 조회:

service:cupixworks-api "kgo4s6" "trade_task_traces"
timerange: 2026-08-03T17:30:00Z .. 2026-08-03T17:32:00Z

Slow 요청 로그 (핵심 필드만 발췌):

{
  "@timestamp": "2026-08-03T17:31:10.422Z",
  "message": "[200] GET /api/v1/facilities/kgo4s6/trade_task_traces (Api::V1::TradeTaskTracesController#index)",
  "duration": 10640.37,
  "serialization": { "duration": 8038 },
  "db": 768.72,
  "view": 0.11,
  "pagination": { "per_page": 100, "total_pages": 1, "current_page": "1", "total_entries": 72 },
  "params": {
    "record_id": "140677",
    "per_page": "100",
    "page": "1",
    "fields": ["id", "uuid", "status", "analyzed_at", "record", "capture", "workarea", "trade"],
    "facility_key": "kgo4s6"
  },
  "user_agent": "cupix-sitetrack-preprocessor-agent",
  "team": { "domain": "accoes", "id": 816 },
  "controller": "Api::V1::TradeTaskTracesController",
  "action": "index",
  "environment": "production",
  "request_id": "87f2361d-7f86-4986-9743-0e3e108492c8"
}

동일 endpoint · 동일 facility (kgo4s6) · 동일 total_entries (72) 요청의 지연 비교 (Datadog 쿼리 service:cupixworks-api "trade_task_traces" -bulk, 2026-08-03T14:00Z..18:00Z):

17:31:10Z  duration=10640ms  serialization=8038ms  db=768ms  total_entries=72   ← slow
17:46:45Z  duration=  107ms  serialization=  54ms  db= 23ms  total_entries=72   ← warm
17:59:57Z  duration=  121ms  serialization=  86ms  db= 25ms  total_entries=72   ← warm

또한 동일 endpoint 에서 훨씬 더 많은 891건을 반환하는 다른 facility 요청도 warm 상태에서는 400-600ms 로 완료되어 (ciw1lc at 17:28), 데이터 볼륨이 아닌 캐시 상태가 dominant factor 임을 확인.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

없음. 1건의 slow request 로 error budget 소진이 크지 않고, 자동 preprocessor agent 가 warm 상태 진입 후 정상 latency 로 돌아왔다. 아래 단기 개선 티켓 발행 권장.

단기 개선 (1주 이내)#

• app/serializers/trade_task_trace_serializer.rb:11-14: _record/_capture/_workarea/_trade 대신 preloaded association 을 직접 사용하는 attribute 정의로 전환하거나, 캐시 미스 배치 로딩을 도입한다. default_joins.includes(:record, :capture, :workarea, :trade) 로 이미 preload 하고 있으므로 associaton 을 그대로 직렬화하는 편이 캐시 경로보다 예측 가능하다. — 방향만 결정하고 다른 serializer 도 동일 패턴을 공유하므로 (app/serializers/editing_entity_serializer.rb:8 등 총 10+ 파일) 영향 범위를 먼저 조사할 것.
• app/models/concerns/cachable.rb:58-70: fetch_cache 를 Rails.cache.read_multi / write_multi 기반의 배치 인터페이스로 확장하여 288건을 1-2회 왕복으로 병합. 미스 시 find_by_id 대신 where(id: missing_ids) 로 in-clause 조회.
• APM: Cupix::QueryOption::TradeTaskTrace 에 serialization.duration > 1000ms alarm 추가 (아래 Monitoring 참고).

장기 개선 (재발 방지)#

• Cachable pattern 을 유지하려면 write-through 캐시 warmup 워커 를 도입하여 신규/변경된 trade_task_trace 및 그 associations 를 after_commit 에서 이미 populate 하고 있는지 검증 (cachable.rb:23-52 write_cache 가 실제로 실행되는 flow 확인 필요).
• Serializer 계층에서 Rails.cache 를 직접 호출하는 패턴 자체를 재고: FastJsonapi::ObjectSerializer 의 캐시 옵션 또는 페이지 단위 fragment cache 로 전환하면 288회 왕복 문제를 근본적으로 제거할 수 있다.
• APM 대시보드에 resource_name 별 serialization.duration / duration 비율 시계열 추가 → 유사한 cache-miss cascade 패턴을 다른 컨트롤러에서 조기 발견.

Monitoring#

Datadog timeseries widget 쿼리 (release dashboard 에 그대로 임베드 가능):

• p95 latency of the endpoint:

p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::tradetasktracescontroller#index,env:production}

• Slow (>1s) request 수:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::tradetasktracescontroller#index,env:production,@duration:>1s}.as_count()

• Serialization duration p95 (log-based facet — attribute @serialization.duration):

p95:logs.serialization.duration{service:cupixworks-api,@controller:Api::V1::TradeTaskTracesController,@action:index,env:production}

@serialization.duration 는 request 로그에 이미 노출되는 필드이지만 Datadog log metric 으로 export 되어 있어야 위 쿼리가 실데이터를 반환한다. facet 미등록 시 log-based metric 을 먼저 생성.

• 알림: serialization.duration > 1000ms 30분 창에서 3건 이상 발생 시 warning.

Risk Assessment#

• Risk level: low (14일 창 1건, 자동 agent 만 영향, 재요청 시 warm 캐시로 정상화)
• 예상 복잡도: standard (serializer + cachable concern 리팩터, 유사 패턴 공유하는 serializer 다수 존재하여 영향 범위 파악 필요)