RCA: Api::V1::ReferencesController#update_meta_by_key latency (30712ms)

Overview#

What Happened#

2026-07-16 01:20:09 KST 에 cupixworks-api (us-west-2, tenant cupix) 에서 PUT /api/v1/references/6272866/meta/prop 요청 한 건이 30,712 ms 만에 HTTP 200 으로 완료되었다. 에러는 발생하지 않았지만 latency 클러스터로 감지되었으며, 동일 리소스에 대한 나머지 요청은 통상 1–4 초 범위에서 완료되고 있다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-16 01:20:09 KST — Slow request 발생 (trace_id=3210919768923393599, duration 30,712 ms).
2. 2026-07-16 01:20:40 KST — 동일 trace 의 완료 로그 (Meta updated by key: 'prop', [200] PUT /api/v1/references/6272866/meta/prop) 가 Datadog 에 기록됨. 컨트롤러 응답까지 마무리.
3. 2026-07-16 01:20:09 KST 이후 지속 — 동일 endpoint 로 초당 다수 호출이 계속 관측되나, 이후 duration 은 정상 범위 (max ~4.4s).

Error Log#

Datadog Logs

resource_name: Api::V1::ReferencesController#update_meta_by_key
service: cupixworks-api
occurrences: 1
avg_ms: 30712
max_ms: 30712
sample_trace_id: 3210919768923393599

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-16 01:20:09 KST
• 최근 발생: 2026-07-16 01:20:09 KST

Root Cause Summary#

이 클러스터는 단일 slow-trace 이벤트다 — HTTP 200 으로 성공한 요청이지만 응답까지 30.7 초가 걸렸다. update_meta_by_key 는 요청 본문을 파싱해 @model.meta[key] 에 대입하고 @model.save 를 호출한다. Reference 모델의 meta 컬럼은 Metable concern 을 통해 Cupix::Util::FlexibleHash 로 serialize 되는 YAML/JSON blob 이라 부분 업데이트가 불가능하며, key 하나만 바뀌어도 전체 blob 이 UPDATE 된다. 이어서 EntityIndexable#after_commit 이 동기적으로 Elasticsearch 에 client.index 를 호출하고, Cachable#after_commit :write_cache 가 캐시를 갱신한다. 동일 Reference (id 6272866) 에 대해 초당 다수의 prop meta update 가 몰리는 상황 (BIM 정합 편집 UI 특성) 에서 row-level lock 대기 + ES 인덱싱 왕복 지연 중 하나가 튀면서 tail latency 가 30 초 수준까지 늘어난 것으로 판단된다. 로그와 메트릭 모두 이 한 건만 outlier 이며 정상 범위 (avg ~1–4s) 를 벗어난 지속적 회귀는 아니다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/metable_controller.rb:42 (MetableController#update_meta_by_key)
• Failure point (latency source): app/controllers/concerns/metable_controller.rb:51 (@model.save) 및 그 이후의 동기 after_commit 콜백

def update_meta_by_key
  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
    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
    # ...
  rescue Cupix::Errors::Parameter => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10004', reason: e.to_s, message: e.message)
  else
    render_json 200, @model.meta[params[:meta_key]]

    Cupix::Logger.info("Meta updated by key: '#{params[:meta_key]}' - keys: #{Cupix::Util::Parser.all_depth_keys(@model.meta[params[:meta_key]]).join('|')}", class: @model.class.name, function: __method__, module: 'MetableController')
  end
end

meta 컬럼은 부분 업데이트를 지원하지 않는 serialized blob 이다:

module Metable
  extend ActiveSupport::Concern

  module ClassMethods
  end

  included do
    serialize :sys, coder: Cupix::Util::FlexibleHash.new
    serialize :meta, coder: Cupix::Util::FlexibleHash.new
  end
end

Reference#save 후 동기적으로 실행되는 두 개의 after_commit 콜백이 존재한다. 첫째, ES 인덱싱은 백그라운드 job 이 아닌 인라인 HTTP 호출이다:

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

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

둘째, Cachable 도 after_commit 에서 캐시를 다시 쓴다:

after_commit :write_cache

기대 동작: meta[params[:meta_key]] 을 갱신하고 즉시 응답 (수백 ms 수준). 실제 동작: Reference.meta blob 전체 UPDATE + Elasticsearch::Model.client.index 왕복 + write_cache 를 트랜잭션 커밋 시점에 동기 실행. 동일 row 에 대해 짧은 간격으로 여러 요청이 몰리는 경우 (Datadog 로그상 동일 endpoint 로 초당 다수 호출) row-level lock 대기 또는 ES 클러스터의 순간적 응답 지연으로 인해 tail latency 가 30 초까지 튈 수 있다.

Log Evidence#

Datadog query (trace id 로 단일 요청 스코프):

service:cupixworks-api trace_id:3210919768923393599

Result — 완료 로그 2건만 존재하며 에러는 없다:

{
  "timestamp": "2026-07-16 01:20:40",
  "status": "info",
  "message": "Meta updated by key: 'prop' - keys: ver|threed|visible|tm|user_scale|def.ver|def.point.ver|def.point.def.ver|def.point.def.def_type|def.point.def.pick.ver|def.point.def.pick.pano|def.point.def.pick.ray|def.point.def.pair.ver|def.point.def.pair.pano|def.point.def.pair.ray",
  "class": "Reference",
  "function": "update_meta_by_key"
}

{
  "timestamp": "2026-07-16 01:20:40",
  "status": "info",
  "message": "[200] PUT /api/v1/references/6272866/meta/prop (Api::V1::ReferencesController#update_meta_by_key)"
}

동일 endpoint 의 호출 빈도 확인 (지난 2일, 최근 편집 활동):

service:cupixworks-api "Meta updated by key" @class:Reference

Result — 200개의 최신 로그가 반환되며 (cursor 로 더 있음), 다수의 timestamp 가 초 단위로 붙어 있다 (예: 2026-07-16 01:39:44 에 3건, 01:39:42 에 3건, 01:39:40 에 3건). BIM 정합 편집 UI 가 point/pick/pair 등 다양한 property 를 짧은 간격으로 반복 저장하는 워크플로우다.

latency 메트릭 (지난 24시간, max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::referencescontroller_update_meta_by_key}):

정상 범위 max: 0.26–4.37 seconds
문제 이벤트 duration: 30.712 seconds (span 기준)

정상 구간이 수 초 이내이므로 30 초는 명확한 outlier 다. trace_id:3210919768923393599 status:error 검색은 0건 — 서버 예외/외부 시스템 에러 로그는 없다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. 단일 slow-trace 이벤트로 사용자 데이터 유실 없음. 즉시 반영해야 할 코드 변경은 확인되지 않았다. 재발 여부 관찰을 우선한다.

단기 개선 (1주 이내)#

• APM span 분해로 30초 이벤트의 병목 세분화: Datadog trace 3210919768923393599 를 UI 에서 열어 postgres.query, elasticsearch.query, rails.action_controller 등 sub-span 중 어느 구간이 지연되었는지 확인. 방향만 잡으면 이후 조치의 근거가 명확해진다.
• 동일 Reference row 에 대한 write 병목 완화 검토: app/controllers/concerns/metable_controller.rb:42-69 의 save 를 save(touch: false) 로 바꾸거나, meta[key] 만 갱신하는 partial update 경로 (예: SQL-level jsonb_set 로의 이관 또는 Reference 의 meta 컬럼을 jsonb 로 마이그레이션) 도입 여부를 데이터 팀과 논의. serialized blob 을 매 요청마다 통째로 UPDATE 하는 패턴은 tail latency 를 필연적으로 만든다.
• _entity_update_document 를 async 로 분리 검토: app/models/concerns/entity_indexable.rb:172-182 의 Elasticsearch::Model.client.index 는 요청 스레드를 블록한다. Sidekiq job 으로 옮기면 API 응답 latency 를 ES 응답 시간으로부터 분리할 수 있다. 다만 인덱스 지연이 read-after-write 계약에 미치는 영향을 검토 필요.

장기 개선 (재발 방지)#

• meta 컬럼 마이그레이션: serialize :meta, coder: FlexibleHash 를 Postgres jsonb 로 이관해 부분 update (jsonb_set) 를 사용. row-level lock 유지 시간을 극적으로 단축.
• BIM 정합 편집 UI 의 debounce/batch 도입 협의: 초당 수 회 발생하는 point/pick/pair 저장을 프런트엔드에서 debounce 하거나 서버 측 batch endpoint 로 통합. 조율 필요 항목이므로 자동 code-fix 대상 아님.
• update_meta_by_key p99 latency 알람 설정: 회귀를 조기 감지하기 위한 SLO 기반 알람.

Monitoring#

Release dashboard timeseries widget 용 쿼리 (모두 timeseries-safe 문법):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::referencescontroller_update_meta_by_key}

max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::referencescontroller_update_meta_by_key}

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

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::referencescontroller_update_meta_by_key}.as_rate()

Alarm 후보: p99 > 10s for 5m on Api::V1::ReferencesController#update_meta_by_key — 통상 최대치가 ~4s 인 점을 감안한 여유값.

Risk Assessment#

• Risk level: low (단일 이벤트, 응답 성공, 데이터 유실 없음)
• 예상 복잡도: standard (단기 개선의 span 분해는 trivial, jsonb 이관은 critical)