RCA: Api::V1::CategoriesController#bulk (33.8s latency)

Overview#

What Happened#

2026-07-07 22:37 KST, cupixworks-api (us-west-2, tenant cupix) 에서 PUT /api/v1/categories (bulk delete 6 categories) 요청이 33,803ms 소요되어 latency 클러스터로 감지되었다. HTTP 응답은 200 성공이었지만, p95 대비 크게 벗어난 outlier로 error-sweeper 가 수집했다. 같은 endpoint 에서 22:37~22:39 사이 4건의 요청이 10초 초과로 실행되어 짧은 시간대의 동시성/부하 상황과 상관관계가 관측된다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-07 22:37:23 KST — PUT /api/v1/categories 요청 시작 (trace_id 2869332536857477033).
2. 2026-07-07 22:37:56 KST — SiteinsightsService::EventProducer 가 "Publishing 6 delete events for Category" 로그 출력 (요청 시작 후 약 33초 지점).
3. 2026-07-07 22:37:56 KST — 동일 초 내에 "Publishing 0/6", "Published 0/6", "Published 0 delete events for Category" 순차 기록 (실제 발행된 이벤트 count = 0).
4. 2026-07-07 22:37:58 KST — [200] PUT /api/v1/categories (Api::V1::CategoriesController#bulk) 응답 로그. 총 latency 33,803ms.
5. 2026-07-07 22:39:44 KST — 같은 endpoint 에서 추가로 slow 요청 관측 (>10s, 2건 동시).
6. 2026-07-07 22:37~23:07 KST — 동일 endpoint 의 다른 요청들은 정상 latency 로 200 응답 (평시 baseline 확인).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CategoriesController#bulk",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 33803,
  "max_ms": 33803,
  "sample_trace_id": "2869332536857477033"
}

Trace 관련 애플리케이션 로그 (Datadog trace_id:2869332536857477033):

2026-07-07 22:37:56  info  Publishing 6 delete events for Category
2026-07-07 22:37:56  info  Publishing 0/6 delete events for Category
2026-07-07 22:37:56  info  Published 0/6 delete events for Category
2026-07-07 22:37:56  info  Published 0 delete events for Category
2026-07-07 22:37:58  info  [200] PUT /api/v1/categories (Api::V1::CategoriesController#bulk)

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (해당 클러스터), 다만 같은 endpoint 에서 22:37~22:39 KST 사이 slow(>10s) 요청 총 4건 관측
• 최초 발생: 2026-07-07 22:37:23 KST
• 최근 발생: 2026-07-07 22:37:23 KST

Root Cause Summary#

Api::V1::CategoriesController#bulk 는 BulkableRepository#bulk! 에서 요청받은 items(6개)에 대해 순차 처리한다. bulk_action = 'delete' 인 경우 _models.find_each 로 각 Category 를 하나씩 CategoryRepository#delete → Category#perform_delete! → Category#trash! (state machine transition, Elasticsearch reindex, cascading callbacks) 로 처리한다. Datadog 애플리케이션 로그가 요청 시작 33초 후에야 EventProducer 단계(Publishing 6 delete events) 에 도달했다는 사실은 삭제 이전 단계 (per-item DB 조회 + trash! 상태 전이 + Elasticsearch 리인덱스 콜백 + _parent.updatable_by? 권한 계산) 에서 대부분의 시간이 소진되었음을 의미한다. main category 삭제 시 children.untrashed.ids 를 포함해 Task.exists? / Element.exists? 두 개의 확인 쿼리를 매 아이템마다 수행하며, permission_joins (category_repository.rb:102-234) 는 9개 이상의 LEFT JOIN 서브쿼리를 포함하는 무거운 권한 계산 SQL 이다. 여기에 22:37~22:39 KST 에 동일 endpoint 동시 요청 4건이 몰린 동시성 요인이 겹쳐 33.8초 latency 가 발생한 것으로 판단된다. 오류나 예외는 없었고 (HTTP 200), 재발이 지속되지 않았다 (동일 시간대 이후 정상 latency).

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/categories_controller.rb:1 — Api::V1::CategoriesController includes BulkableController and DocumentRefreshableController.
• Bulk action dispatcher: app/controllers/concerns/bulkable_controller.rb:25-45.
• Repository core: app/repositories/concerns/bulkable_repository.rb:5-79 — bulk! method.
• Per-item delete: app/repositories/category_repository.rb:33-46 → BaseRepository#delete → Category#perform_delete! (Cyclable::perform_delete! → trash!).
• Event publish: app/services/cupix/siteinsights_service/event_producer.rb:17-31.

def bulk
  _bulked_ids = []
  _invalid_items = []
  case params[:bulk_action]
  when 'create'
    _bulked_ids, _invalid_items = factory_instance.bulk(params, current_user: @current_user, current_team: @current_team, partial_mode: true)
  when 'update', 'delete'
    _bulked_ids, _invalid_items = repository_instance.bulk(params, current_user: @current_user, current_team: @current_team, partial_mode: true)
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'Invalid bulk_action')
  end
  # ...
  render_json 200, _bulked_ids, nil, _invalid_items
end

bulk! 에서 delete 는 find_each 로 한 건씩 순차 처리한다:

when 'delete'
  _models.find_each.with_index do |model, index|
    _repository = self.class.new(review: _review, current_user: current_user, model: model, parent: _parent)
    _repository.model.skip_siteinsights_event_publish! if _repository.model.respond_to?(:skip_siteinsights_event_publish!)
    _repository.delete
  rescue StandardError => e
    _invalid_items << {
      index: index
    }.merge(Cupix::Util::ErrorParser.parse_error(e))
    next
  end

_models 는 default_joins (facility left join) + permission_joins 를 거친 relation 으로, find_each 는 각 배치마다 id > last_id 로 재쿼리한다. Category 6건에 대해 매 반복마다 다음이 발생한다:

1. CategoryRepository#delete (app/repositories/category_repository.rb:33-46) 가 삭제 가드 쿼리 2개(Task, Element)를 실행.
2. super → BaseRepository#delete → model.perform_delete! → Cyclable#perform_delete! → trash! (state_machine transition).
3. trash! 는 after_transition 콜백에서 (프로젝트 관례상) Elasticsearch reindex, cache invalidation, 자식 category(ancestryable) cycle_state 전파를 트리거.

def delete
  category_ids = [@model.id]
  category_ids += @model.children.untrashed.ids if @model.category_type == 'main'

  if ::Task.untrashed.where(category_id: category_ids).exists?
    raise Cupix::Errors::Entity.new(code: 'ENT30001', reason: 'Cannot delete category because it is used elsewhere')
  end

  if ::Element.untrashed.where(category_id: category_ids).exists?
    raise Cupix::Errors::Parameter.new(code: 'SI14001', reason: 'The category cannot be deleted because it contains elements')
  end

  super
end

권한 계산은 permission_joins 에서 이루어지며 9개 이상의 상관 서브쿼리를 포함하는 무거운 SQL 이다:

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  # ...
  _select = "MAX(review_user_permissions.permission) AS review_user_permission,
    MAX(review_group_permissions.permission) AS review_group_permission,
    MAX(review_public_permissions.permission) AS review_public_permission,
    MAX(facility_user_permissions.permission) AS facility_user_permission,
    MAX(facility_group_permissions.permission) AS facility_group_permission,
    MAX(facility_system_group_permissions.permission) AS facility_system_group_permission,
    MAX(team_user_permissions.permission) AS team_user_permission,
    MAX(team_group_permissions.permission) AS team_group_permission,
    MAX(team_system_group_permissions.permission) AS team_system_group_permission,
    MAX(GREATEST(...)) AS applied_permission"
  # ...

마지막으로 EventProducer 가 실행되지만 실제 event_count = 0 이었다 (skip_siteinsights_event_publish 로 인해 skip 된 경우 또는 event_builder 가 empty batch 를 반환한 경우). 이 단계는 로그 타임스탬프상 요청 시작 후 33초 지점에 도달했다:

def produce(records = [], event_type: nil, force: false, batch_size: 10000)
  return if Rails.env.test?
  return if records.empty?

  record_size = records.size
  Cupix::Logger.info("Publishing #{record_size} #{event_type} events for #{@model_name}", ...)
  @event_builder.build_events_in_batch(records, event_type: event_type, batch_size: batch_size, force: force) do |event|
    @event_count += event.count
    Cupix::Logger.info("Publishing #{@event_count}/#{record_size} #{event_type} events for #{@model_name}", ...)
    @event_publisher.publish(event)
    Cupix::Logger.info("Published #{@event_count}/#{record_size} #{event_type} events for #{@model_name}", ...)
  end
  Cupix::Logger.info("Published #{@event_count} #{event_type} events for #{@model_name}", ...)
end

기대 동작 vs 실제 동작: 6건 정도의 category delete 는 baseline 상 수백 ms 안에 완료되어야 한다 (같은 endpoint 의 다른 요청들은 정상 응답 관측). 실제로는 delete 단계가 약 33초 소요됐고, event publish 로그가 요청 시작 후 33초 지점에서 처음 나타났다. 오류는 발생하지 않았다 (HTTP 200).

Log Evidence#

Datadog query (재현용):

service:cupixworks-api trace_id:2869332536857477033

Trace 내 애플리케이션 로그 (총 5건 — 모두 요청 종료 근처에만 존재):

{
  "timestamp": "2026-07-07 22:37:56",
  "status": "info",
  "message": "Publishing 6 delete events for Category",
  "class": "Cupix::SiteinsightsService::EventProducer",
  "function": "produce"
}
{
  "timestamp": "2026-07-07 22:37:56",
  "status": "info",
  "message": "Publishing 0/6 delete events for Category"
}
{
  "timestamp": "2026-07-07 22:37:56",
  "status": "info",
  "message": "Published 0/6 delete events for Category"
}
{
  "timestamp": "2026-07-07 22:37:56",
  "status": "info",
  "message": "Published 0 delete events for Category"
}
{
  "timestamp": "2026-07-07 22:37:58",
  "status": "info",
  "message": "[200] PUT /api/v1/categories (Api::V1::CategoriesController#bulk)"
}

관측 포인트: 5개 로그 중 4개가 22:37:56 초 안에 발생, 마지막은 22:37:58 로 응답. 요청 시작은 22:37:23 (첫 로그와의 gap ≈ 33초). 즉 delete 루프(6 items)가 약 33초 소요됨.

인접한 slow bulk 요청 4건 확인 (Datadog query service:cupixworks-api "Api::V1::CategoriesController#bulk" @duration:>10000, 7d 범위):

2026-07-07 22:39:44  [200] PUT /api/v1/categories (Api::V1::CategoriesController#bulk)
2026-07-07 22:39:44  [200] PUT /api/v1/categories (Api::V1::CategoriesController#bulk)
2026-07-07 22:37:58  [200] PUT /api/v1/categories (Api::V1::CategoriesController#bulk)  <- 이 클러스터
2026-07-07 22:37:56  [200] PUT /api/v1/categories (Api::V1::CategoriesController#bulk)

7일 전체 범위에서 slow(>10s) bulk 요청이 22:37~22:39 KST 라는 2분 창에 4건 몰려 있고 다른 시간대에는 관측되지 않았다. Endpoint 자체는 24h 내 수십 건이 모두 정상 latency 로 200 응답 (동일 query 로 확인).

Baseline 정상 요청 예 (수십 건 중 일부):

2026-07-07 22:46:32  [200] PUT /api/v1/categories
2026-07-07 22:46:28  [200] PUT /api/v1/categories
2026-07-07 22:46:24  [200] PUT /api/v1/categories
...

Datadog metric 확인 시도 (trace.rails.request / trace.rack.request.duration): 두 metric 모두 series 가 비어 반환됨. Datadog APM span 세부 분석은 불가.

Status board (svc:cupixworks-api scope): 최근 7일 이내 cupixworks-api service degraded 인시던트가 5회 발생 (2026-06-30, 07-01, 07-02, 07-03, 07-06) — 모두 root_cause_types: ["unknown"] 으로 종결됨. 이번 이벤트와 유사한 짧은 latency 상승 창이 반복되는 패턴이 있다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. HTTP 200 성공, 재발 지속 없음, 오류/예외 없음. 이 단일 outlier 만으로 hotfix 를 롤아웃할 근거가 부족.
• 다만 APM span 상세 캡처를 활성화하여 bulkable_repository.rb:47-58 delete 루프의 아이템별 latency 를 관측 가능하게 해야 한다 (Cupix::Logger.info 로 아이템별 진입/종료 로그 추가 검토 — bulkable_repository.rb:48 반복 시작 지점).

단기 개선 (1주 이내)#

• 관측성 강화: bulkable_repository.rb find_each 루프 내부에 아이템 진입/종료 로그(class, function, model_name, id, duration_ms) 를 info 레벨로 추가. 33초가 실제로 어느 아이템 / 어느 서브스텝에 몰렸는지 다음 재발 시 즉시 판정 가능하게 함.
• 동시성 관측: 같은 endpoint 로의 동시 요청 수 (resource_name:...#bulk) 를 count timeseries 로 대시보드 추가. 22:37~22:39 KST 처럼 짧은 창 동시 요청 spike 가 지표로 나오는지 확인.
• permission_joins 쿼리 프로파일링: category_repository.rb:102-234 SQL 을 EXPLAIN 으로 프로파일링. MAX(GREATEST(...)) + 9개 상관 서브쿼리는 카테고리/facility/team 규모가 큰 tenant 에서 지수적으로 느려질 수 있음.

장기 개선 (재발 방지)#

• Bulk 삭제의 원자화: 현재 find_each 로 아이템별 개별 트랜잭션 + 개별 콜백 실행 구조는 6건에서도 33초가 가능함을 시사. 다수 items 를 하나의 트랜잭션 + batch update 로 처리하고, siteinsights / ES reindex 는 하나의 배치로 위임 (BulkSavePartialJsonToFileWorker 처럼) 검토.
• 비동기화 옵션: bulk delete 를 요청 시 accepted(202) 로 응답하고, Sidekiq worker 로 처리 후 사용자에게 완료 알림. 대량 삭제 UX 상 자연스러움.
• status-board 반복 패턴 조사: 최근 7일 내 5회 발생한 svc:cupixworks-api::unknown degraded 인시던트와 이 outlier 의 상관관계 조사. 공통 시간대/tenant/endpoint 있는지 detector 를 튜닝하여 root_cause_types 를 좁힐 수 있는지 검토.

Monitoring#

REQUIRED SUB-SKILL 준수: 아래 쿼리는 monitor-only 문법(| stats, count by(...)) 을 배제하고 timeseries widget 에 그대로 렌더 가능한 형태로 작성.

• 특정 endpoint p95/p99 latency (rack request)

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::categoriescontroller#bulk}

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::categoriescontroller#bulk}

• Slow request count (>10s) — logs based metric

service:cupixworks-api resource_name:"Api::V1::CategoriesController#bulk" @duration:>10000000000

(참고: trace.rack.request.duration metric 이 태그 조회 시 빈 결과로 반환되는 것을 확인. 배포된 metric 이름 정확도는 dashboard 편집 시 재확인 필요 — uncertain, needs verification)

• 알림 임계값 제안: p95 > 5s 지속 5분, p99 > 15s 지속 5분

Risk Assessment#

• Risk level: low
  • 단일 outlier, HTTP 200 성공, 사용자에게 오류 미노출.
  • 다만 짧은 시간 창에 동시 slow 요청 4건이 몰린 패턴은 재발 가능성을 시사.
• 예상 복잡도: standard
  • 관측성 추가 및 SQL 프로파일링은 표준 개선 작업. 근본적 배치화/비동기화는 별도 프로젝트 규모.