RCA: Api::V1::EditingsController#index latency (avg 22466ms)

Overview#

What Happened#

2026-07-18 12:01 KST 경 production us-west-2 환경의 cupixworks-api 서비스에서 GET /api/v1/editings (Api::V1::EditingsController#index) 요청 1건이 22.4초 동안 실행되어 latency 클러스터로 감지되었다. Datadog trace 로그를 확인한 결과 총 소요 시간 22,420ms 중 serialization 단계가 21,252ms를 차지했으며, DB(753ms) 및 view(0.11ms) 시간은 정상 범위였다. 즉, Elasticsearch 검색이나 SQL 쿼리 자체가 느린 것이 아니라 응답 20건을 EditingSerializer로 직렬화하는 과정에서 병목이 발생했다.

Quick Facts#

Affected Teams#

Datadog trace 로그에서 확인된 slow request 는 1건이지만, 동일한 endpoint 는 최근 7일간 @duration:>5s 조건으로 지속적으로 반복 조회되고 있다(주로 admin 도메인). 따라서 편집 큐를 조회하는 내부 운영자 그룹이 상시 영향권.

Timeline#

1. 2026-07-18 12:01:14 KST — GET /api/v1/editings 요청 도착 (per_page=20, total_entries=462)
2. 2026-07-18 12:01:14 ~ 12:01:39 KST — 요청 처리, DB 쿼리 753ms 후 EditingSerializer 직렬화 21.3초 소요
3. 2026-07-18 12:01:39 KST — 200 응답 반환 (총 22,420ms)
4. 2026-07-18 12:01:14 KST — error-sweeper 가 avg_duration 22466ms latency 클러스터로 감지

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::EditingsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 22466,
  "max_ms": 22466,
  "sample_trace_id": "924077456036494870"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (동일 endpoint 의 @duration:>5s 슬로우 요청은 최근 7일 상시 반복 관측)
• 최초 발생: 2026-07-18 12:01 KST
• 최근 발생: 2026-07-18 12:01 KST

Root Cause Summary#

EditingsController#index 는 Elasticsearch 로 매칭된 20건의 Editing 을 EditingSerializer 로 직렬화하면서 각 record 마다 stat 속성을 계산한다. stat 은 Statisticable::Editing#statistic_to_json → all_statistic 을 호출하는데, all_statistic (app/models/concerns/statisticable.rb:47) 은 statistics.group(:name, :phase).maximum(:created_at) 형태의 GROUP BY 쿼리를 record 별로 개별 실행하는 N+1 패턴이다. 편집 이력이 오래된 record 의 경우 statistics 테이블에 rows 가 수천 건 누적되므로 GROUP BY 하나에 수백 ms 가 걸리고, 20건 × 수백 ms 가 누적되어 serialization 전체가 21초에 도달했다. DB 총합이 753ms 로 보이는 것은 각 개별 쿼리 시간이 trace 상 db 지표에 완전히 집계되지 않았거나(Ruby 직렬화 시간과 섞여 있음), 대부분의 시간이 Ruby 측 transform_values(&:to_datetime) 과 stat JSON 조립에 소모되었기 때문이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/editings_controller.rb:11 — EditingsController#index
• Elasticsearch search: app/repositories/editing_repository.rb:174-179
• Serializer 진입: app/serializers/editing_serializer.rb — attribute :stat (via StatAttribute include, line 64)
• Failure point (N+1): app/models/concerns/statisticable.rb:47-53 — all_statistic per record

def index
  editing_query_option = Cupix::QueryOption::Editing.new(get_query_option(enable_current_team: false), params)
  editings = repository_instance.search(editing_query_option)

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

repository_instance.search 는 Elasticsearch 결과를 받아 SearchResult 를 반환하며, 이후 render_api 안에서 EditingSerializer 가 각 record 를 순회한다.

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

Elasticsearch 응답 자체는 20건만 페이지네이션되어 문제 없다(로그 db: 753ms, total_entries: 462).

attribute :meta

attribute :assigned_at
attribute :capture_started_at
attribute :capture_finished_at
attribute :created_at
attribute :updated_at

include StateAttribute
attribute :state_updated_at

include QualityAssuranceAttribute::Reviewable
include StatAttribute
include CyclableAttribute
include PriorityAttribute

StatAttribute (line 64) 가 serializer 에 stat 을 추가하고, 이 attribute 는 아래 concern 을 호출한다.

def stat
  statistic_to_json
end

def statistic_to_json
  stats = all_statistic

  {
    editing: _editing_stat_json(stats),
    count: _count_stat_json
  }
end

핵심 병목:

attr_writer :preloaded_all_statistic

def all_statistic
  return @preloaded_all_statistic if defined?(@preloaded_all_statistic)

  statistics.group(:name, :phase)
            .maximum(:created_at)
            .transform_values(&:to_datetime)
end

기대 동작: request 한 번당 총 statistics 조회는 1회 (bulk preload) 또는 관계 preload 를 통해 상수 시간. 실제 동작: @preloaded_all_statistic 가 index action 경로에서 세팅되지 않아 record 20건에 대해 각각 statistics.group(:name, :phase).maximum(:created_at) 를 실행 → N+1. _editing_stat_json (statisticable/editing.rb:29) 은 11개 상태 × 1 phase 조회, _get_stat (statisticable.rb:59-69) 은 우선 sys[original_key] 를 확인하지만 sys 컬럼이 비어 있으면 stats hash 를 참조하므로 GROUP BY 결과가 여전히 계산돼야 함. 편집 이력이 긴 record 는 statistics 테이블에서 수백~수천 row 를 그룹핑하게 되어 record 당 latency 가 크게 늘어난다.

한편 EditingSerializer 에는 이 외에도 count 속성 4종(panos_count, videos_count, video_panos_count, pointclouds_count) 이 있으나 이들은 Editing 테이블 컬럼(app/models/concerns/searchable/editing.rb:99-102 에 정의된 인덱스와 동일한 이름) 이므로 attribute lookup 은 O(1). stat_total_entities/changed/reviewed 역시 editings 테이블 컬럼(db/schema.rb:1626-1628) 이라 fast. 따라서 21초의 실질 원인은 statistics N+1 하나로 좁혀진다.

Log Evidence#

Datadog query:

service:cupixworks-api "GET /api/v1/editings" @duration:>10s

Trace 로그(요약, Datadog raw JSON 발췌):

{
  "controller": "Api::V1::EditingsController",
  "action": "index",
  "duration": 22420.11,
  "view": 0.11,
  "db": 753.55,
  "serialization": { "duration": 21252 },
  "params": {
    "filter": "editing_type:normal",
    "per_page": "20",
    "order_by": "estimated_finish_at",
    "page": "1",
    "sort": "asc",
    "fields": [
      "id", "team", "team.domain", "editor", "escalated_by", "facility",
      "record", "level", "reviewers", "meta", "panos_count", "videos_count",
      "video_panos_count", "pointclouds_count", "video_length", "state",
      "stat", "created_at", "updated_at", "estimated_finish_at",
      "priority_score", "preview_quality"
    ]
  },
  "pagination": { "next_page": 2, "per_page": 20, "total_pages": 24, "total_entries": 462 },
  "http": { "status_code": 200, "method": "GET" },
  "team": { "domain": "admin", "id": 133 },
  "user": { "id": 47812, "email": "migo.jang@cupix.com" },
  "@timestamp": "2026-07-18T03:01:39.073Z",
  "environment": "production",
  "region": "us-west-2"
}

핵심 지표:

• serialization.duration = 21252 ms → 총 22.4초 중 95% 가 serialization 단계
• db = 753.55 ms → SQL 쿼리 합계는 정상 범위 (single-record N+1 이 20건 = 40ms/record 수준)
• view = 0.11 ms → render 자체는 순간
• pagination.per_page = 20, total_entries = 462 → 응답 볼륨은 크지 않음
• 요청 fields 에 stat 이 포함됨 → serializer 가 Stat::Editing#stat 을 호출하도록 트리거

동일 endpoint 최근 7일 (2026-07-11 ~ 2026-07-18) @duration:>5s 조회 결과 30건 (limit 도달) 이며 대부분 200 응답. 즉 이 slow-serialization 은 이 인스턴스에 국한된 spike 가 아니라 상시 패턴.

주변 시간대 관련 에러(2026-07-18 02:55~03:10Z): Cupix::PubSub::Subscribers::UserRecipeGenerator 에서 private method 'service_jwt' 에러 6건, ActiveRecord::LockWaitTimeout (PanosController) 3건 관측 — 모두 별 이슈이며 EditingsController 지연과 인과관계 없음.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• EditingSerializer 렌더링 경로에서 all_statistic 를 bulk-preload — app/repositories/base_repository.rb:70-112 #search 가 최종 records 를 얻은 뒤, 반환 직전에 record ids 로 statistics 를 한 번에 조회하여 각 record 의 preloaded_all_statistic= 에 세팅한다. 구현 방향:
  • 대상 파일: app/repositories/editing_repository.rb 의 _search 후반부 또는 app/repositories/base_repository.rb#search 의 SearchResult 조립 직전.
  • 조회 예시(구현은 하지 않음, 방향만): Statistic.where(statisticable_type: 'Editing', statisticable_id: ids).group(:statisticable_id, :name, :phase).maximum(:created_at) 결과를 id 단위로 파티션해 contents.each { |e| e.preloaded_all_statistic = ... } 로 주입.
  • 근거: statisticable.rb:45-48 이 이미 attr_writer :preloaded_all_statistic + memoization 을 지원하도록 설계돼 있으므로 진입점만 추가하면 됨.
• 응답 fields 에서 stat 을 client 가 실제로 필요한 경우에만 요청하도록 admin UI 를 확인 — 목록 뷰에서 필요 없다면 요청에서 제거하는 것만으로 latency 즉시 해소. 단, UI 팀과 조율 필요 → 자동화된 code-fix 대상 아님(별도 트랙).

단기 개선 (1주 이내)#

• _get_stat 우선순위 재검토 — statisticable.rb:59-69 는 sys[original_key] 를 먼저 확인하므로, 대부분의 상태 timestamp 를 sys 컬럼(jsonb / hstore) 에 캐싱하고 있으면 GROUP BY 를 건너뛸 수 있다. sys 컬럼이 실제 얼마나 채워져 있는지 샘플 record 로 확인 후, backfill 로 statistics 최신 값을 sys 에 반영하는 배치 작업을 검토.
• APM span 세분화 — EditingSerializer#call 및 Statisticable::Editing#statistic_to_json 에 Datadog custom span 을 추가해 record 당 statistics 조회 시간을 정량화. 향후 회귀 감지에 활용.

장기 개선 (재발 방지)#

• 모든 index endpoint 에 대한 serialization budget 모니터 — Rails request log 의 serialization.duration 을 Datadog dashboard 로 노출하고, serialization > 5s 시 warn.
• Serializer N+1 lint — CI 에 bullet 또는 유사한 도구를 붙여 serializer 진입 시점의 statistics/associations preload 를 강제.
• statistics 테이블 파티션/보존 정책 — 이력이 오래된 편집의 statistics rows 가 무한 누적되지 않도록 최근 N일만 유지하고 나머지는 압축/삭제.

Monitoring#

Datadog 대시보드에 아래 timeseries widget 을 추가한다. 각 쿼리는 그대로 timeseries 위젯에 들어가도 유효한 metrics/logs 문법을 사용했다.

• Editings index p95 latency:

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

• Editings index serialization duration (log-based, 필드 존재 시):

avg:logs.duration.serialization{service:cupixworks-api,controller:api::v1::editingscontroller}

(위 metric 이 아직 없다면 log-based metric 으로 service:cupixworks-api controller:Api::V1::EditingsController + @serialization.duration facet 를 생성해야 한다.)

• @duration:>10s slow request 개수:

sum:logs.hits{service:cupixworks-api,controller:api::v1::editingscontroller,action:index,@duration:>10000}.as_count()

Risk Assessment#

• Risk level: medium — 200 응답이 유지되므로 데이터 무결성 이슈는 아니지만 admin 운영자 UX 심각히 저하, 22초 이상은 CloudFront/ALB timeout 에 근접
• 예상 복잡도: standard — preload 훅 추가는 repository/base_repository 한 곳 수정으로 가능. 다만 다른 statisticable 모델(Capture, Sitetrack, RecordStatus, Deviation) 에서도 유사 패턴 있을 수 있어 회귀 테스트 필요.