Api::V1::ClustersController#update_meta (avg 1805ms, max 1805ms)

RCA: Api::V1::ClustersController#update_meta Latency (1805ms)

Overview#

What Happened#

2026-05-27T19:49:06Z에 cupixworks-api 서비스의 PUT /api/v1/clusters/1349545/meta 요청이 1802ms 소요되었다. 전체 요청 시간의 72.5%인 1307ms가 데이터베이스에서 소비되었으며, 동일 시간대 동일 엔드포인트의 다른 요청들(44-139ms)에 비해 약 30-40배 느렸다.

Quick Facts#

Field	Value
resource_name	`Api::V1::ClustersController#update_meta`
duration	`1802.02ms` (DB: 1307.33ms)
top_frame	`app/controllers/concerns/metable_controller.rb:22`
env	production, us-west-2
cluster_id	1349545
user	Troy Yocom (tyocom@weoneil.com, team: weoneil)

Timeline#

19:49:03.751Z — 동일 사용자가 cluster 1349545에 check_uploading 요청 (237ms)
19:49:04.157Z — cluster 1349545에 resource 생성 요청 (59ms)
19:49:06.160Z — update_meta 요청 시작, 1802ms 소요 (DB: 1307ms)
19:49:06.376Z — Meta 업데이트 완료 로그 기록 (13개 키 업데이트)
2026-05-28 — Error sweeper 감지, RCA 시작

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::ClustersController#update_meta",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1805,
  "max_ms": 1805,
  "sample_trace_id": "7819127167900726603"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-05-27T19:49:03.843Z
최근 발생: 2026-05-27T19:49:03.843Z
영향 범위: 단일 사용자(Troy Yocom), 단일 클러스터(1349545). 동일 엔드포인트의 다른 요청은 정상 속도.

Root Cause Summary#

update_meta 요청이 cluster 1349545의 meta 필드에 13개 키(refinement.alignment_preview.*)를 업데이트할 때, @model.save 호출이 Eventable after_update 콜백 체인을 트리거하여 EventFactory.create! → legacy_create_event_attribute_changes → legacy_create_event_objects 및 Cachable#write_cache 직렬화를 순차 실행했다. 동시에 동일 클러스터에 대한 resource 생성(check_uploading, POST resources) 요청이 2초 이내에 연달아 발생하면서 row-level lock contention이 발생하여 DB 대기 시간이 1307ms까지 증가한 것으로 판단된다.

Technical Analysis#

Code Path#

Entry point: app/controllers/concerns/metable_controller.rb:14 (update_meta 메서드)
핵심 save 호출: app/controllers/concerns/metable_controller.rb:22
After update callback: app/models/concerns/eventable/callbacks.rb:34-35
Event 생성: app/models/concerns/eventable/events/update.rb:9-16
Event attribute changes 생성: app/models/concerns/eventable/events/base.rb:28-37
After commit cache write: app/models/concerns/cachable.rb:23-52

1. update_meta 액션 — meta 파싱 및 save

app/controllers/concerns/metable_controller.rb:14-30ruby

def update_meta
  if !@model.updatable_by?(current_user) && (@review.present? && !@review.updatable_by?(current_user))
    raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied')
  end

  begin
    @model.meta = JSON.parse(request.raw_post)
    @model.skip_entrypoint_flush = true if @model.respond_to?(:skip_entrypoint_flush)
    @model.save
  rescue JSON::ParserError
    raise Cupix::Errors::Parameter.new(code: 'ARG10004', reason: 'Failed to parse meta value')
  else
    render_json 200, @model.meta
    Cupix::Logger.info("Meta updated - keys: #{Cupix::Util::Parser.all_depth_keys(@model.meta).join('|')}", class: @model.class.name, function: __method__, module: 'MetableController')
  end
end

@model.save(line 22)가 트랜잭션을 열고 UPDATE SQL을 실행한 후 after_update 콜백을 트리거한다.

2. After update 콜백 — Event 생성 체인

app/models/concerns/eventable/callbacks.rb:34-35ruby

after_update do |model|
  Eventable::Events::Update.create_event(model) if model.event_creation_on_update?
end

event_creation_on_update?는 기본적으로 true를 반환하므로(action.rb:11), 모든 Cluster update에서 이벤트가 생성된다.

3. Event 생성 — DB insert 3회 이상

app/models/concerns/eventable/events/update.rb:9-16ruby

def _create_event(model)
  event = EventFactory.new(current_user: model.current_user).create!(model)

  legacy_create_event_attribute_changes(model, event)
  legacy_create_event_objects(model, event)

  event
end

app/models/concerns/eventable/events/base.rb:28-36ruby

def legacy_create_event_attribute_changes(model, event)
  return unless model.saved_changes?
  return if Cupix::Migrate::NotificationService.use_notification_service?

  model.saved_changes.each do |key, value|
    unless %w[sys meta cached updated_at created_at].include? key
      event.event_attribute_changes.create!(name: key, before: value[0], after: value[1])
    end
  end
end

meta 필드 변경은 %w[sys meta cached updated_at created_at] 제외 목록에 포함되어 event_attribute_changes에는 기록되지 않지만, EventFactory.create!와 후속 publish_event, Analytics.track 호출은 여전히 실행된다.

4. After commit — Cache 직렬화 및 Redis write

app/models/concerns/cachable.rb:23-29ruby

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)

serialized_json은 ClusterSerializer를 인스턴스화하여 전체 cluster를 직렬화한다. 큰 meta 객체가 있으면 직렬화 비용도 증가한다.

5. Counter culture — Capture 레코드 업데이트

app/models/cluster.rb:40-42ruby

counter_culture :capture,
                column_name: proc { |model| model.untrashed? ? 'clusters_count' : nil },
                column_names: { ::Cluster.untrashed => :clusters_count }

counter_culture는 save 시 capture 테이블에 대한 추가 UPDATE를 발행하여, 동시 접근 시 lock 경합을 유발할 수 있다.

Log Evidence#

Datadog 검색 쿼리:

text

service:cupixworks-api "ClustersController" "update_meta" @duration:>500

text

service:cupixworks-api @request_id:"f562a0c2-8aaa-4def-a49e-1c0044de303c"

text

service:cupixworks-api "1349545"

핵심 로그 — 느린 요청:

json

{
  "timestamp": "2026-05-27T19:49:06.160Z",
  "request_id": "f562a0c2-8aaa-4def-a49e-1c0044de303c",
  "method": "PUT",
  "path": "/api/v1/clusters/1349545/meta",
  "controller": "Api::V1::ClustersController",
  "action": "update_meta",
  "status": 200,
  "duration": 1802.02,
  "db": 1307.33,
  "view": 0.48,
  "host": "ip-10-1-144-228.us-west-2.compute.internal",
  "params": { "id": "1349545", "fields": ["prop", "skat"] },
  "user": "tyocom@weoneil.com",
  "user_agent": "cupix-agent"
}

Application 로그 — Meta 업데이트 완료:

text

[2026-05-27T19:49:06.376Z] [MetableController] [update_meta] [Cluster]
Meta updated - keys: refinement.alignment_preview.filepath|refinement.alignment_preview.name|refinement.alignment_preview.prop.h|refinement.alignment_preview.prop.inh|refinement.alignment_preview.prop.inw|refinement.alignment_preview.prop.pivot.x|refinement.alignment_preview.prop.pivot.y|refinement.alignment_preview.prop.r|refinement.alignment_preview.prop.tx|refinement.alignment_preview.prop.ty|refinement.alignment_preview.prop.ver|refinement.alignment_preview.prop.w|refinement.alignment_preview.ver

동시 요청 비교 — 동일 사용자가 2초 간격으로 같은 클러스터에 3개 요청:

text

19:49:03.751Z  PUT /api/v1/clusters/1349545/resources/preview_image/check_uploading  237.16ms (db: 21.77ms)
19:49:04.157Z  POST /api/v1/clusters/1349545/resources                                59.33ms (db: 27.71ms)
19:49:06.160Z  PUT /api/v1/clusters/1349545/meta                                    1802.02ms (db: 1307.33ms)

동일 엔드포인트 정상 요청 비교:

text

19:48:53Z  cluster 1349544  update_meta  139.22ms (db: 50.29ms)
19:49:04Z  cluster 1349546  update_meta   44.64ms (db: 12.89ms)
19:49:24Z  cluster 1349547  update_meta   47.23ms (db: 16.88ms)
19:49:36Z  cluster 1349549  update_meta   49.86ms (db: 17.75ms)

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Row-level lock contention: 동일 클러스터(1349545)에 대한 연속 요청(resource 생성 → meta update)이 DB lock 대기를 유발	동일 사용자가 2초 내 3개 요청 발행(check_uploading, resource create, update_meta). DB 시간이 1307ms로 전체의 72.5%. 다른 클러스터(1349546, 1349547)는 동시간대 12-50ms로 정상.	동일 호스트의 다른 에러/경고 없음. lock 대기를 직접 확인하는 로그는 부재.	Confirmed
H2	전역 DB 과부하: 전체 데이터베이스가 느려서 모든 요청이 영향받음	같은 시간대 다른 호스트에서 CapturesController#index가 914ms(db: 810ms) 소요	동일 사용자의 직후 요청(1349549)이 49ms로 정상. 동일 시간대 다른 클러스터 update_meta도 44-47ms로 정상. 영향이 특정 클러스터에 국한됨.	Rejected
H3	Event 콜백 체인의 과도한 DB 쿼리: EventFactory + attribute_changes + event_objects 생성이 대량 INSERT 유발	after_update 콜백에서 최소 Event INSERT 1회 + publish_event + Analytics.track 실행 확인 (base.rb:10-18). 단, meta 변경은 attribute_changes 제외 목록에 포함.	meta 필드만 변경 시 event_attribute_changes는 0건. 단독으로 1307ms를 설명하기 어려움. 정상 update_meta도 동일 콜백을 실행하지만 12-50ms만 소요.	Contributing factor

Fix Recommendation#

즉시 조치 (Critical)#

이 이슈는 단발성(1회 발생)으로 즉시 수정이 필요한 수준은 아님
모니터링을 추가하여 동일 패턴 반복 여부를 확인

단기 개선 (1주 이내)#

cupix-agent가 동일 클러스터에 대해 resource 생성과 meta update를 연속 발행하는 패턴을 확인하고, 클라이언트 측에서 meta update를 resource 생성 완료 후 약간의 delay를 두고 발행하도록 조정
app/models/concerns/eventable/action.rb:11 — Cluster의 event_creation_on_update?를 meta-only 변경 시 false를 반환하도록 override 고려. meta 변경만으로는 event 생성이 불필요할 수 있음

장기 개선 (재발 방지)#

update_meta 액션에서 @model.save 대신 update_column(:meta, ...) 또는 callback-free update를 사용하여 Eventable/Cachable 콜백을 건너뛰는 옵션 검토. meta 업데이트는 이벤트 추적이 불필요한 경우가 많음
동일 리소스에 대한 동시 쓰기를 큐잉하거나 optimistic locking 도입으로 lock contention 완화
counter_culture 콜백이 meta-only 변경에도 capture 레코드를 불필요하게 터치하는지 확인 (clusters_count는 변경되지 않으므로 no-op일 수 있으나 lock은 획득할 수 있음)

Monitoring#

update_meta 엔드포인트의 p95/p99 latency 추적
동일 cluster_id에 대한 동시 요청 패턴 감지

text

service:cupixworks-api resource_name:"Api::V1::ClustersController#update_meta" @duration:>500ms

text

service:cupixworks-api resource_name:"Api::V1::ClustersController#update_meta" @db:>500

Risk Assessment#

Risk level: low
예상 복잡도: trivial
단발성 이벤트로, 동일 클러스터에 대한 동시 쓰기가 겹치면서 발생한 일시적 lock contention. 재발 시 영향은 개별 요청 지연에 국한되며 데이터 손실은 없음.