RCA: ElementTracesController#summary Latency (avg 3147ms, max 3412ms)

Overview#

What Happened#

2026-05-26 05:54:59~05:55:12 UTC 사이에 Api::V1::ElementTracesController#summary 엔드포인트에서 평균 3147ms, 최대 3412ms의 응답 지연이 발생했다. Python 자동화 클라이언트(Python-urllib/3.11)가 동일한 record_id=129795로 약 30초 동안 64건의 동시 요청을 보냈으며, 해당 record의 element_traces 테이블에 대한 GROUP BY 쿼리가 DB 레벨에서 ~1850ms 소요되면서 전체 응답 시간이 3초 이상으로 증가했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-05-26T05:54:50Z — Python 자동화 클라이언트가 record_id=129795로 대량 동시 요청 시작
2. 2026-05-26T05:54:55Z — 첫 번째 slow request 발생 (8,651ms, DB 2,451ms)
3. 2026-05-26T05:54:57Z — 최대 지연 발생 (10,031ms, DB 2,304ms + queuing)
4. 2026-05-26T05:55:12Z — 마지막 slow request 종료
5. 2026-05-26T05:55:56Z — 다른 record_id(130096)에 대한 요청은 95-118ms로 정상 응답

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementTracesController#summary",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 3147,
  "max_ms": 3412,
  "sample_trace_id": "1620643578312888432"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2 (APM 샘플 기준, 실제 slow request는 64건)
• 최초 발생: 2026-05-26T05:54:59.404Z
• 최근 발생: 2026-05-26T05:55:12.612Z

Root Cause Summary#

record_id=129795에 대한 ElementTrace.untrashed.where(record_id: 129795).group(:element_id, :record_id).size 쿼리가 대량의 행을 스캔하면서 DB 처리 시간이 ~1850ms로 증가했다. 이 상황에서 Python 자동화 클라이언트(9개 IP, 13.124.199.x/24)가 동시에 64건의 동일 요청을 보내면서 DB connection pool 경합과 request queuing이 발생하여 일부 요청은 최대 10초까지 지연되었다. 다른 record_id(129969, 130056, 130096 등)는 15-183ms로 정상 응답하므로, 특정 record에 연결된 element_traces 행 수가 비정상적으로 많은 데이터 특성 문제와 클라이언트의 동시 요청 패턴이 복합적으로 작용한 결과이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/document_refreshable_controller.rb:13
• Repository delegation: app/repositories/concerns/document_refreshable_repository.rb:25-34
• Parameter validation: app/repositories/concerns/document_refreshable_repository/element_trace.rb:10-12
• Scope chain: Cyclable::BaseScope.untrashed at app/models/concerns/cyclable/base_scope.rb:35-60

Summary action은 controller에서 repository_instance.summary(params)를 호출한다:

def summary
  summary_result = repository_instance.summary(params)
  render_json summary_result.present? ? 200 : 304, { summary: summary_result }
end

Repository의 summary 메서드에서 실제 쿼리가 실행된다:

def summary(params = {})
  check_refresh_documents(params)

  _group_by = params[:group_by] || _default_group_by
  summaries = self.class.current_class.untrashed.where(required_parameters(params)).group(_group_by).size

  { key: _group_by, value: summaries }
rescue StandardError => e
  raise e
end

ElementTrace 전용 오버라이드에서 record_id 필터와 group_by 기본값을 정의한다:

def required_parameters(params = {})
  { record_id: params[:record_id] }
end

def check_refresh_documents(params)
  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'record_id is required') if params[:record_id].blank?
end

def _default_group_by
  %i[element_id record_id]
end

untrashed scope는 cycle_state 조건을 추가한다:

def self.untrashed
  return all unless has_attribute?(:cycle_state)

  query = where(cycle_state: %w[created archiving archived])

  # cycle_state가 nil인 레코드도 포함 (레거시 데이터)
  if has_attribute?(:trashed_at) && has_attribute?(:purged_at)
    query = query.or(where(cycle_state: nil, trashed_at: nil, purged_at: nil))
  elsif has_attribute?(:purged_at)
    query = query.or(where(cycle_state: nil, purged_at: nil))
  else
    query = query.or(where(cycle_state: nil))
  end
  # ...
end

최종 생성되는 SQL은 대략 다음과 같다:

SELECT element_id, record_id, COUNT(*) AS size
FROM element_traces
WHERE record_id = 129795
  AND (cycle_state IN ('created','archiving','archived') OR cycle_state IS NULL)
GROUP BY element_id, record_id

현재 인덱스 index_element_traces_on_rcs는 [record_id, cycle_state, status_id]로 구성되어 record_id 필터링은 가능하지만, GROUP BY element_id 정렬을 위한 커버링 인덱스가 아니므로 filesort가 발생한다.

Log Evidence#

Datadog 쿼리로 확인한 slow request 분포:

Query: service:cupixworks-api *ElementTracesController* *summary*
Time: 2026-05-26T05:54:50Z to 2026-05-26T05:55:20Z
Result: 74 logs

record_id=129795에 대한 64건의 slow request 통계:

Max duration: 10,031.70ms (DB: 2,304ms, View: 440ms)
Avg duration: ~3,060ms
DB time range: 1,600 - 2,451ms
View time range: 350 - 811ms
Hosts: 3 (ip-10-1-19-190, ip-10-1-144-228, ip-10-1-80-134) - load balanced
Client IPs: 9 unique IPs in 13.124.199.x/24
User-Agent: Python-urllib/3.11

비교: 다른 record_id의 동일 시점 응답 시간:

record_id=129969: 15-22ms (2 requests)
record_id=130056: 43-46ms (2 requests)
record_id=129986: 300-740ms (6 requests)
record_id=130096: 95-118ms (46 requests, at 05:55:56Z)

요청 간 duration 격차(10,031ms vs 3,060ms avg)는 동시 요청 64건이 3개 서버의 DB connection pool을 포화시키면서 request queuing이 발생한 것을 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

1. record_id=129795의 데이터 규모 확인: 해당 record에 연결된 element_traces 행 수를 확인하고, 비정상적으로 많다면 데이터 정리 또는 archiving 필요.
2. Rate limiting 적용: Python-urllib/3.11 클라이언트가 동일 endpoint에 30초 내 64건 동시 요청을 보내는 패턴에 대해 rate limit 설정 검토.

단기 개선 (1주 이내)#

1. 복합 인덱스 추가: [record_id, element_id] 인덱스를 추가하면 WHERE record_id = ? GROUP BY element_id, record_id 쿼리가 인덱스만으로 처리 가능(covering index).

   • 파일: 새 migration 생성
   • 대상 인덱스: add_index :element_traces, [:record_id, :element_id], name: 'idx_element_traces_record_element'

2. Summary 결과 캐싱: 동일 record_id에 대한 summary 결과를 짧은 TTL(30-60초)로 캐싱하면 동시 요청 부하를 흡수할 수 있다.

   • 파일: app/repositories/concerns/document_refreshable_repository.rb:25-34

장기 개선 (재발 방지)#

1. 대량 데이터 record에 대한 summary pre-computation: element_traces가 특정 임계값(예: 10,000건) 이상인 record에 대해서는 background job으로 summary를 미리 계산하여 캐시에 저장.
2. API rate limiting 인프라: 자동화 클라이언트의 burst 요청 패턴을 제어할 수 있는 endpoint-level rate limiter 도입.
3. Slow query monitoring: Rails 레벨에서 1초 이상 소요되는 ActiveRecord 쿼리를 warn 레벨로 로깅하여 조기 탐지.

Monitoring#

• DB 쿼리 시간 모니터링:

service:cupixworks-api @http.url:*/element_traces/summary* @duration:>2000

• Summary endpoint P95 latency 알림 설정 (임계값: 2000ms)
• record_id 별 element_traces 행 수 주기적 확인 (비정상 증가 탐지)

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 영향 범위가 특정 record + 자동화 클라이언트로 한정되어 있으며, 사용자 대면 서비스에 대한 직접적 영향은 제한적. 인덱스 추가로 근본적 해결 가능.