RCA: CapturesController#update_meta_by_key Latency (1417ms)

Overview#

What Happened#

2026-05-27 11:36 UTC에 cupixworks-api 서비스의 Api::V1::CapturesController#update_meta_by_key 엔드포인트에서 1417ms 응답 지연이 발생했다. 단일 PUT 요청이 500ms SLO를 초과하여 latency 클러스터로 감지되었다. us-west-2 리전에서 발생.

Quick Facts#

Timeline#

1. 2026-05-27T11:36:29Z — update_meta_by_key 요청 1417ms 소요 (trace ID: 5316498009195741298)
2. 2026-05-27T11:36:29Z — error-sweeper latency 클러스터 생성
3. 2026-05-27 — RCA 분석 수행

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::CapturesController#update_meta_by_key",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1417,
  "max_ms": 1417,
  "sample_trace_id": "5316498009195741298"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-05-27T11:36:29.349Z
• 최근 발생: 2026-05-27T11:36:29.349Z

Root Cause Summary#

update_meta_by_key 액션의 @model.save 호출이 Capture 모델에 등록된 다수의 콜백을 연쇄 실행하면서 총 1417ms의 지연을 유발했다. 주요 원인은: (1) Eventable::Events::Update.create_event에서 전체 Capture를 Eventable::CaptureSerializer로 직렬화하며 team, facility, record, level 연관 객체를 개별 쿼리로 로드하는 N+1 문제, (2) Cachable#write_cache에서 serialized_json을 통해 다시 전체 Capture를 직렬화하고 Redis에 기록하는 중복 작업, (3) meta 필드의 YAML 직렬화(FlexibleHash.dump)로 인한 오버헤드가 복합적으로 작용한 결과이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/metable_controller.rb:42 (update_meta_by_key 액션)
• JSON 파싱 및 meta 업데이트: metable_controller.rb:48-49
• Failure point (latency): metable_controller.rb:51 (@model.save)
• Eventable 콜백 트리거: app/models/concerns/eventable/events/base.rb:7-26
• Event 직렬화: app/factories/event_factory.rb:142-153
• Cache 기록: app/models/concerns/cachable.rb:23-52

update_meta_by_key는 요청 본문에서 JSON을 파싱하여 모델의 meta 해시에 키를 업데이트한 후 @model.save를 호출한다:

begin
  parsed_meta = JSON.parse(request.raw_post)
  @model.meta[params[:meta_key]] = parsed_meta
  @model.skip_entrypoint_flush = true if @model.respond_to?(:skip_entrypoint_flush)
  @model.save

save 호출 시 Capture 모델의 after_update 콜백에서 Eventable::Events::Update.create_event가 실행된다. 이 메서드는 Event 레코드를 생성하면서 EventFactory를 통해 전체 Capture를 직렬화한다:

def _create_serialized_eventable(eventable_model)
  _eventable_serializer = eventable_model_serializer(self.model)

  return if _eventable_serializer.nil?

  _serialized_json = _eventable_serializer.new(eventable_model, {
    params: { event: self.model },
    is_collection: false
  }).serializable_hash[:data][:attributes]

  self.model.serialized_eventable_json = _serialized_json
end

이 직렬화 과정에서 Eventable::CaptureSerializer가 team, facility, record, level 연관 객체를 개별 쿼리로 로드한다 (N+1). 또한 Analytics.track과 Cupix::EventService.publish_event 호출이 순차적으로 실행된다:

def create_event(model)
  return nil if invalid_event?(model)

  begin
    event = _create_event(model)
    reason = extract_reason(event, model)
    properties = build_properties(model)

    track_event(model, reason, properties)

    Cupix::EventService.publish_event([event])
    Cupix::Event.publish(event.serializable_hash(stringify_nested_fields: false))

after_commit 콜백에서 Cachable#write_cache가 다시 전체 Capture를 직렬화하여 Redis에 기록한다:

def write_cache(force: false)
  prior_to_write_cache
  _cache_keys = []
  _cache_value = nil

  if cachable? && respond_to?(:serialized_json)
    _cache_value = self.send(:serialized_json)

Log Evidence#

동일 시간대에 capture 37345에 대해 다수의 update_meta_by_key 호출이 연속 발생하며 각각 CPNotification과 FeedService 처리를 트리거한 것을 확인:

Datadog query: service:cupixworks-api "CapturesController" "update_meta_by_key"
Time range: 2026-05-27T10:30:00Z to 2026-05-27T12:00:00Z

[200] PUT /api/v1/captures/37345/meta/calibrated_videos (Api::V1::CapturesController#update_meta_by_key)
[200] PUT /api/v1/captures/37345/meta/mark (Api::V1::CapturesController#update_meta_by_key)
[200] PUT /api/v1/captures/37345/meta/uncalibrated_video_ids (Api::V1::CapturesController#update_meta_by_key)

각 meta 업데이트가 CPNotification 이벤트를 생성한다. capture 37345에 대해 1초 이내에 3개의 meta key 업데이트가 순차 발생하며, 각각이 독립적으로 Event 생성 + Serialization + Cache write 사이클을 수행:

{
  "event_id": 83148149,
  "action": "update",
  "model_type": "Capture",
  "model_id": 37345,
  "attribute_changes": "[{\"name\":\"updated_at\",\"before\":\"2026-05-27T11:58:17Z\",\"after\":\"2026-05-27T11:58:29Z\"},{\"name\":\"video_length\",\"before\":0.0,\"after\":1200.587546},{\"name\":\"recording_fps\",\"before\":0.0,\"after\":2.0}]"
}

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/controllers/concerns/metable_controller.rb:51 — meta-only 업데이트 시 Eventable 콜백을 스킵하는 옵션 추가. skip_entrypoint_flush처럼 skip_event_creation 플래그를 도입하여 meta key 업데이트만 수행할 때 불필요한 Event 생성을 방지.
• app/models/concerns/eventable/callbacks.rb — meta 필드만 변경된 경우 (saved_changes.keys == ['meta', 'updated_at']) Event 생성을 스킵하는 조건 추가.

단기 개선 (1주 이내)#

• app/factories/event_factory.rb:142-153 — _create_serialized_eventable에서 N+1 방지를 위해 association preloading 추가. includes(:team, :facility, :record, :level) 적용.
• Cachable의 serialized_json과 Eventable의 직렬화가 동일 데이터를 중복 생성 — 캐시된 결과를 재사용하도록 리팩토링.

장기 개선 (재발 방지)#

• meta 업데이트를 위한 경량 저장 경로 도입: @model.update_column(:meta, ...) 또는 JSON 패치 방식으로 콜백을 우회하는 전용 메서드 구현.
• 이벤트 생성 및 캐시 쓰기를 비동기 Sidekiq job으로 분리하여 요청 응답 시간에서 제외.
• FlexibleHash의 YAML 직렬화를 JSON 또는 MessagePack으로 전환하여 직렬화 오버헤드 감소.

Monitoring#

• APM 메트릭으로 update_meta_by_key p95 응답 시간 모니터링:

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::capturescontroller#update_meta_by_key} by {env}

• Eventable 직렬화 시간을 custom metric으로 추가하여 콜백 체인의 병목 가시화
• 500ms 초과 시 알림 설정:

trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::capturescontroller#update_meta_by_key} > 500ms

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard — meta-only 업데이트 시 콜백 스킵 조건 추가는 기존 skip_entrypoint_flush 패턴을 따르며 비교적 안전. 단, 이벤트 스킵이 downstream 시스템(notification, feed)에 미치는 영향을 검증해야 함.