RCA: Api::V1::CapturesController#update latency (avg 35s, max 83s)

Overview#

What Happened#

2026-06-24 13:21 KST부터 약 5시간 동안 cupixworks-api 의 Api::V1::CapturesController#update 엔드포인트가 평균 35초, 최대 83초의 응답 시간을 보였다. 112건의 느린 PUT 요청이 us-west-2, ap-southeast-1, ap-southeast-2, ap-northeast-1 4개 리전에서 모두 발생했으며 응답 상태는 모두 200이라 에러 로그는 없다. 동일 시간 창의 svc:cupixworks-api::unknown incident에 7개의 다른 클러스터가 함께 묶여 있어 서비스 전반의 디그레이드와 동반 발생한 latency 클러스터다.

Quick Facts#

Affected Teams#

영향 받은 capture id는 로그 샘플 기준 720794, 78154, 720894, 720906, 720903, 720847, 2364 등 다수로, 단일 facility/tenant 가 아닌 다수 클라이언트가 영향 받음.

Timeline#

1. 2026-06-24 13:21 KST — 첫 느린 update 요청 (cluster first_seen)
2. 2026-06-24 14:02 KST — svc:cupixworks-api::unknown incident open (status-board 기준)
3. 2026-06-24 14:32 KST — 본 latency 클러스터가 incident 에 attach
4. 2026-06-24 18:42 KST — 본 클러스터 마지막 발생 (cluster last_seen)
5. 2026-06-24 — RCA 작성. incident 2026-06-24-svc-cupixworks-api--unknown-1 은 작성 시점 open 상태

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#update",
  "service": "cupixworks-api",
  "occurrences": 13,
  "avg_ms": 32510,
  "max_ms": 60891,
  "sample_trace_id": "4237033345100016509"
}

샘플 access log (모두 status 200):

[200] PUT /api/v1/captures/720794 (Api::V1::CapturesController#update)
[200] PUT /api/v1/captures/78154 (Api::V1::CapturesController#update)
[200] PUT /api/v1/captures/720894 (Api::V1::CapturesController#update)

Impact#

• Service: cupixworks-api
• 발생 횟수: 112
• 최초 발생: 2026-06-24 13:21 KST
• 최근 발생: 2026-06-24 18:42 KST

Root Cause Summary#

Api::V1::CapturesController#update 의 hot path 에서 Capture 모델이 EntityUpdates::Child 의 after_update :reset_parent_cached_entity_updates 콜백을 실행한다. 이 콜백은 매 업데이트마다 Cupix::Loader.load (Zeitwerk::Loader.eager_load_all)를 호출한 뒤 ObjectSpace.each_object(Class) 로 Ruby VM 의 모든 클래스를 순회한다. 동시에 Capture 모델에는 70개 이상의 concern 이 mixin 되어 있고 EntityIndexable#_entity_update_document 가 synchronous Elasticsearch index 호출을 한다. 평상시에도 무거운 update 경로가 incident 시간대(svc:cupixworks-api::unknown open)에 더해진 외부 자원 (DB connection, Elasticsearch, Sidekiq enqueue) 의 추가 지연과 결합되면서 평균 35초, 최대 83초의 응답 시간이 관측됐다. 응답 코드는 모두 200 이므로 functional bug 가 아닌 순수 performance/디그레이드 이슈다.

Technical Analysis#

Code Path#

Entry: app/controllers/api/v1/captures_controller.rb:46-50 — controller update 는 단순히 repository 의 update 를 호출하고 super 로 render.

def update
  @model = repository_instance.update(params)

  super
end

Repository: app/repositories/capture_repository.rb:182-194 — super (BaseRepository) 호출 후 set_parameters(params) 그리고 @model.save!. 즉 응답 시간의 대부분은 save! 의 callback 사슬에서 소비된다.

def update(params = {})
  super

  set_parameters(params)

  begin
    @model.save!
  rescue StandardError => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
  end

  @model
end

Capture 모델은 EntityIndexable, EntityUpdates::Child, StaleReview::Capture, Statable::Capture, Thumbnailable, SpacetimeEntity::Capture 등 70개 이상의 concern 을 포함한다 (app/models/capture.rb:1-74). 그 중 update 경로에 직접적으로 비용이 큰 콜백들:

class Capture < ApplicationRecord
  include RecordEntity::Capture
  include EntityIndexable
  include Permissionable::Capture
  include ::Statable::Capture
  include ::Cyclable::Capture
  ...
  include EntityUpdates::Child   # ← reset_parent_cached_entity_updates
  ...
end

Failure point 1 — EntityUpdates::Child after_update 가 Zeitwerk::Loader.eager_load_all + ObjectSpace.each_object(Class) 를 update 마다 실행:

included do
  include ::EntityUpdates

  after_create :reset_parent_cached_entity_updates
  after_update :reset_parent_cached_entity_updates
  ...
end

def reset_parent_cached_entity_updates
  self.class.parent_classes.each do |class_name|
    Cupix::Logger.info("reset #{class_name} (ID: #{self.send("#{class_name.underscore}_id")}) cached entity updates", ...)
    Rails.cache.delete(entity_updates_cache_key(class_name, self.send("#{class_name.underscore}_id")))
  end
end

class << self
  def parent_classes
    Cupix::Loader.load

    ObjectSpace.each_object(Class).select do |model|
      model.superclass == ApplicationRecord && !model.name.include?('::') && !model.name.ends_with?('Permission') && model.respond_to?(:entities) && model.entities.include?(self.name.underscore.to_sym)
    end.map(&:name)
  end
end

class << self
  def load
    case model_load_type.underscore
    when 'load_paths'
      ...
    else
      Zeitwerk::Loader.eager_load_all
    end
  end
end

ObjectSpace.each_object(Class) 는 Ruby VM 전체 클래스 (수만 개) 를 순회하며 select. 결과는 캐시되지 않고 매 update 마다 다시 계산된다. Zeitwerk eager_load_all 은 호출 횟수 cap 이 있어 두 번째부터는 빠르지만 ObjectSpace 순회는 매번 풀비용.

Failure point 2 — EntityIndexable 가 after_commit on: :update 에서 동기적으로 Elasticsearch 에 index 호출:

after_commit :_entity_index_document, on: [:create]
after_commit :_entity_update_document, on: [:update]
after_commit :_entity_delete_document, on: [:destroy]

def _entity_update_document
  return if @skip_index_document == true

  Elasticsearch::Model.client.index(
    index: self.class.entity_index_name,
    id: entity_document_id,
    body: as_entity_indexed_json
  )
rescue StandardError => e
  Cupix::Logger.error("Entity update error - #{e.message}", class: self.class.name, function: __method__)
end

ES cluster 가 느려지면 이 호출이 request 스레드를 그대로 블록한다.

Failure point 3 — StaleReview::Capture 가 around_save + after_save 에서 review touch 와 Sidekiq enqueue:

included do
  include StaleReview

  around_save :touch_reviews_after_save, unless: :skip_touch_reviews?
  after_save :touch_record_after_save, unless: :skip_touch_reviews?
  ...
end

def touch_record_after_save
  return if saved_changes.blank?

  unless (saved_changes.keys & TOUCH_REVIEWS_ATTRIBUTES).blank?
    record.stale_fresh_state unless record.fresh_state_stale?
  end
end

def touch_reviews
  TouchCaptureReviewsWorker.perform_async(id)
end

기대 동작: PUT /captures/:id 가 메타데이터 한 줄을 갱신한다. 1초 이내 응답이 기대값.

실제 동작: save 의 콜백 체인이 매번 (a) Zeitwerk eager_load + 전체 ObjectSpace 순회, (b) 동기 ES index, (c) Redis 호출, (d) DB cache invalidation, (e) Sidekiq enqueue 를 직렬로 수행 → 평균 35초, 최대 83초.

Log Evidence#

Datadog 쿼리 (재현):

service:cupixworks-api "CapturesController" "update"

service:cupixworks-api "captures/720794"

샘플 결과 (last 12h, 모두 status 200):

2026-06-24 20:50:20  info  [200] PUT /api/v1/captures/720794 (Api::V1::CapturesController#update)
2026-06-24 20:50:18  info  [200] PUT /api/v1/captures/78154  (Api::V1::CapturesController#update)
2026-06-24 20:50:14  info  [200] PUT /api/v1/captures/720794 (Api::V1::CapturesController#update)
2026-06-24 20:50:12  info  [200] PUT /api/v1/captures/78154  (Api::V1::CapturesController#update)
2026-06-24 20:50:02  info  [200] PUT /api/v1/captures/720894 (Api::V1::CapturesController#update)

캡처 빈도 (last 30m, log sample):

6  captures/720906
6  captures/720894
5  captures/720903
3  captures/78154
3  captures/720794
3  captures/719848

→ 소수 capture 가 짧은 시간에 여러 번 PUT 됨 (클라이언트가 자동 저장/포즈 업데이트). 이 빈도가 콜백 체인의 누적 부하를 만든다.

Datadog warn/error 검색은 0건:

service:cupixworks-api status:warn "CapturesController#update"  → 0
service:cupixworks-api status:(warn OR error) "timeout"         → 0 (관련 결과 없음, Lambda timeout 만 검색됨)
service:cupixworks-api status:(warn OR error) ("Elasticsearch" OR "slow query") → 0

→ 명시적 에러는 없음. 순수 latency 클러스터로, span duration >500ms 필터로만 Datadog 가 잡아낸 사례.

Status-board 응답 (bun run cli/incident-board.ts for-cluster ...):

{
  "scope": "svc:cupixworks-api::unknown",
  "active": {
    "id": "2026-06-24-svc-cupixworks-api--unknown-1",
    "started_at": "2026-06-24T05:02:30.056Z",
    "last_event_at": "2026-06-24T09:42:52.648Z",
    "cluster_ids": [
      "7a8c442a-...", "6646d865-...", "5d4a9d4b-...", "047d3696-...",
      "d4db4525-...", "cc009704-...",
      "e9b399a2-43a9-48c0-a9d6-5500cb0b5f31",
      "66a28888-..."
    ]
  }
}

→ 동일 시간 창에 cupixworks-api 의 다른 클러스터 7개가 함께 발생. 단일 엔드포인트 문제가 아니라 서비스 전체 디그레이드의 한 단면일 가능성이 큼.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/entity_updates/child.rb:11-19 — parent_classes 결과를 클래스 단위로 메모이즈해야 한다. 매 update 마다 Cupix::Loader.load + ObjectSpace.each_object(Class) 를 호출하는 것은 hot path 에 절대 부적합. 부팅 시 한 번 계산해 클래스 변수에 저장하거나 Rails.cache 또는 thread-local 캐시 사용을 검토. 변경 범위가 크므로 Capture 같은 hot model 에 한해 우선 적용.
• 임시 mitigation 으로 Cupix::Loader.load 호출을 production 환경에서 noop 으로 만들거나 (Zeitwerk eager-load 는 부팅 시 이미 끝나 있어야 함) parent_classes 의 결과를 ||= 로 캐시.

단기 개선 (1주 이내)#

• app/models/concerns/entity_indexable.rb:172-182 의 _entity_update_document 를 동기 호출에서 Sidekiq 비동기 worker 로 분리. ES 지연이 API 응답 시간에 직접 노출되지 않도록.
• app/models/concerns/stale_review/capture.rb:32-38 touch_record_after_save 가 동기적으로 record.stale_fresh_state 를 호출 — touch_reviews 처럼 worker 로 이전 검토.
• Capture 의 update path 에 Datadog 의 span tag (콜백별 소요시간) 추가해 어떤 콜백이 실제로 가장 큰 비중을 차지하는지 정량화. (코드 예시는 작성하지 않음 — 방향만.)

장기 개선 (재발 방지)#

• Capture 모델의 70+ concern 구조 자체가 update path 의 모든 콜백을 직렬화시키는 구조적 문제. 도메인 이벤트 (e.g. CaptureUpdated event publish → consumer worker) 패턴으로 분리해 controller 응답 시간과 부수 효과를 분리.
• cluster_type: latency 클러스터에 대해 APM span 의 child span 소요시간을 RCA 도구가 자동 수집하도록 collector 확장 (현재는 trace_id 만 기록).
• EntityUpdates::Child#parent_classes 같은 reflection 기반 lookup 을 정적 registration 으로 교체 (각 parent 모델이 자신을 등록하는 방식).

Monitoring#

• 추가할 메트릭:

  • Api::V1::CapturesController#update 의 p50/p95/p99 응답 시간 timeseries
  • capture 모델 save 시 콜백별 span 소요시간 (custom Datadog span)
  • ES entity_index_* index 의 indexing latency

• Datadog 쿼리 (release dashboard timeseries widget):

avg:trace.rack.request{service:cupixworks-api,resource_name:api::v1::capturescontroller#update}

avg:trace.rails.request{service:cupixworks-api,resource_name:api::v1::capturescontroller#update}

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::capturescontroller#update}.as_count()

avg:trace.rack.request{service:cupixworks-api,resource_name:api::v1::capturescontroller#update} by {region}

(주: 위 쿼리들은 monitor-only 문법인 | stats, count by(...), threshold suffix 를 포함하지 않는다.)

Risk Assessment#

• Risk level: medium — 응답 코드는 200 이라 functional 문제는 아니지만, 30-80초 응답 시간은 클라이언트 타임아웃 또는 retry storm 으로 이어질 수 있고, 같은 시간 창에 동일 서비스의 7개 다른 클러스터가 함께 발생 중이라 서비스 전체 영향이 더 클 수 있다.
• 예상 복잡도: standard — EntityUpdates::Child#parent_classes 메모이즈는 trivial; ES index async 화는 standard (worker, 인덱스 정합성 처리 필요); 콜백 구조 전반 리팩토링은 critical.