RCA: Api::V1::PanosController#update_meta_by_key latency (11.4s)

Overview#

What Happened#

2026-06-25 07:01 KST에 cupixworks-api (production, us-west-2)에서 Api::V1::PanosController#update_meta_by_key 요청 하나가 11476ms 동안 실행되며 latency 클러스터(duration:>500ms)로 감지되었습니다. 동일 시각에 동일 endpoint 의 정상 요청은 ~263ms 였으므로 이번 한 건은 평소 대비 약 43배 느렸습니다. HTTP 응답은 200 으로 사용자 측 실패는 없었고 다른 status:error 도 발생하지 않았습니다.

Quick Facts#

Affected Teams#

영향 범위는 단일 요청으로 한정. 동일 시간 윈도우(22:01:50Z–22:02:10Z)에는 100건 이상의 동일 endpoint 요청이 정상적으로 처리됨.

Timeline#

1. 2026-06-25 07:01:00 KST — update_meta_by_key 요청들이 burst 로 유입되기 시작 (수십 건/sec, cupix-agent 트래픽).
2. 2026-06-25 07:01:56 KST — 문제 요청 발생, 11476ms 동안 실행 후 200 응답 (first_seen = last_seen).
3. 2026-06-25 07:01:50–07:02:10 KST — 같은 20s 윈도우에 100+ 건의 동일 endpoint 요청 성공 (Datadog log 카운트).
4. 2026-06-25 07:09:5x KST — Pano#_update_document 가 NotFound - attributes_in_database warn 로그를 다수 출력 (관련 패턴, 후술).
5. 이후 동일 cluster_id 의 재발생 없음 (occurrence_count: 1).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#update_meta_by_key",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11476,
  "max_ms": 11476,
  "sample_trace_id": "2362480884664013187"
}

대표적인 정상 요청 로그(같은 분, 다른 트레이스):

{
  "@timestamp": "2026-06-24T22:01:59.899Z",
  "message": "[200] PUT /api/v1/panos/89986911/meta/blurriness (Api::V1::PanosController#update_meta_by_key)",
  "duration": 263.06,
  "db": 122.97,
  "view": 0.09,
  "user_agent": "cupix-agent",
  "team": { "domain": "whitingturner", "id": 140 },
  "params": { "id": "89986911", "fields": ["prop", "skat"] }
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-25 07:01 KST
• 최근 발생: 2026-06-25 07:01 KST
• 사용자 영향: 없음. HTTP 200 으로 응답, 메타 저장은 성공. cupix-agent 자동 파이프라인의 한 단계가 11.4s 늦게 끝났을 뿐 후속 처리는 정상 진행.

Root Cause Summary#

Api::V1::PanosController#update_meta_by_key 의 11.4s 지연은 단일 요청에서만 관찰된 outlier 이며, 일정한 패턴의 latency 회귀가 아니다. 동일 시간/팀/endpoint 에서 평균 ~263ms 로 정상 처리되고 있었고 error 로그도 0건이다. 가장 유력한 근본 원인은 Pano#save 의 after_commit on: [:update] 콜백이 동기로 호출하는 Elasticsearch _update_document 호출이 일시적으로 늦어진 것이다(app/models/concerns/searchable.rb:16-94). 이는 burst 트래픽 (20초간 100+ 건 동시 메타 업데이트) 중 한 건이 ES 네트워크/큐잉 변동에 걸렸을 때 충분히 재현 가능한 시나리오이며, 동시간대에 같은 모델의 _update_document 가 NotFound - attributes_in_database 분기로 빠지면서 partial update 대신 full re-index 경로 (as_indexed_json 전체 + 다중 eager-load) 를 자주 타고 있는 정황도 확인된다. 단일 occurrence 라 코드 변경 없이 모니터링만 강화하는 것이 합리적이다.

Technical Analysis#

Code Path#

• Entry: app/controllers/api/v1/panos_controller.rb:8 — before_action :set_pano
• Action: app/controllers/concerns/metable_controller.rb:42 — update_meta_by_key
• Save callback chain: Pano#save → after_commit on: [:update] → _update_document (app/models/concerns/searchable.rb:16)
• Slowest external call: Elasticsearch update (또는 NotFound 분기에서 _index_document 의 ES index) — 동기 호출

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]]
    # ...
  end
end

@model.save 가 끝나기 전에 Pano 의 Searchable 콜백이 동기로 동작한다:

after_commit on: [:update] do
  _update_document
end

_update_document 내부 동작 — 두 경로 모두 ES 호출이 request thread 안에서 일어남:

def _update_document
  # ...
  if (attributes_in_database = __elasticsearch__.instance_variable_get(:@__changed_model_attributes).presence)
    attributes = if respond_to?(:as_indexed_json)
                   if (attributes_in_database.keys & %w[cached sys]).present?
                     __elasticsearch__.as_indexed_json
                   else
                     # ... partial doc 만 전송
                     __elasticsearch__.as_indexed_json.select { |k, v| column_names.include?(k.to_s) }
                   end
                 else
                   attributes_in_database
                 end

    unless attributes.empty?
      # ES update 호출 (동기)
      results = __elasticsearch__.client.update(request.merge({ index: __elasticsearch__.index_name }))
      # ...
    end
  else
    Cupix::Logger.warn('NotFound - attributes_in_database', class: self.class.name, function: __method__)
    _index_document   # ★ full index 재실행 (eager-load 무거움)
  end

_index_document 는 PanoSerializer 와 eager_loaded (capture, capture_type, camera, level, record, facility, workspace, team) 전체를 끌어와 indexed_json 을 만든다:

class << self
  def eager_loaded
    eager_load({ capture: %i[capture_type camera level] }, :capture, :record, :facility, :workspace, :team)
  end
end
# ...
Searchable.to_searchable_json(self, serializer)

기대 동작: 정상 케이스의 db≈123ms + view≈0.09ms + ES partial update + 기타 = ~263ms. 실제 동작 (문제 요청): 동일 path 가 11476ms. db/view 자체는 변화가 없을 가능성이 높고, request thread 안에서 호출되는 ES 호출(또는 그 직전 as_indexed_json 직렬화)이 늦어진 것으로 보인다. 단일 occurrence 라 트레이스 span 별 시간 분포는 확정할 수 없다 — uncertain, 트레이스 상세 미확보.

Log Evidence#

검색 쿼리:

service:cupixworks-api "update_meta_by_key"
시간: 2026-06-24T22:01:00Z..2026-06-24T22:02:00Z
결과: 100+ 건 (대부분 [200] PUT)

service:cupixworks-api status:error
시간: 2026-06-24T21:55:00Z..2026-06-24T22:10:00Z
결과: 0건

같은 윈도우에 동일 endpoint 가 burst 로 처리되고 있었음 (20초 안에 100+ 건):

[200] PUT /api/v1/panos/90000389/meta/blurriness (Api::V1::PanosController#update_meta_by_key)
[200] PUT /api/v1/panos/90000386/meta/blurriness (Api::V1::PanosController#update_meta_by_key)
[200] PUT /api/v1/panos/90000390/meta/ver       (Api::V1::PanosController#update_meta_by_key)
[200] PUT /api/v1/panos/90000410/meta/ver       (Api::V1::PanosController#update_meta_by_key)
... (총 100+)

정상 요청의 duration / db breakdown (위 Error Log 섹션의 JSON 참고): duration: 263.06 ms, db: 122.97 ms, view: 0.09 ms. 즉 평소 절반은 DB I/O 다.

같은 인스턴스/시간대에 Pano#_update_document 의 NotFound - attributes_in_database warn 이 다수 관찰됨 (full-reindex 분기를 자주 탐):

{
  "timestamp": "2026-06-24T22:09:5x",
  "status": "warn",
  "message": "NotFound - attributes_in_database",
  "class": "Pano",
  "function": "_update_document"
}

이 warn 자체는 latency cluster 의 trace 와 동일한 요청에서 나왔다는 직접 증거는 없지만 (single-trace), _update_document 가 _index_document full-reindex 분기로 분기되는 일이 같은 호스트/같은 분 내에서 흔하다는 정황은 보여 준다.

Status board 결과 (bun run cli/incident-board.ts for-cluster eb263ffc-...):

scope: svc:cupixworks-api::unknown
active: null
recent: 2건의 resolved svc:cupixworks-api::unknown 인시던트 (06-24 일자, latency 와 무관한 status:error 군집)

→ 현재 활성 외부 의존성 outage 와는 무관, 내부 service 스코프이며 status board 가 RCA 단축을 권하지 않는 케이스.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 코드 변경 불필요. 단일 occurrence, HTTP 200, error 0, status board dep:* active 없음. 추가 발생 여부 모니터링.
• 동일 cluster 가 24–48h 내에 다시 잡히면 그때 트레이스 span 상세(trace_id: 2362480884664013187 의 ES/DB breakdown)를 APM 에서 확인해 진단을 좁힌다.

단기 개선 (1주 이내)#

• app/models/concerns/searchable.rb:55-111 의 _update_document 중 attributes_in_database blank 분기(line 107-111)가 _index_document 를 즉시 호출하는 대신 BulkIndexWorker.perform_async 로 위임하는 옵션을 검토. 현재 구조는 동기 ES index (full body) 호출이 request thread 를 점유 → 같은 윈도우의 다른 요청 분포를 보고 cost/benefit 판단.
• 또는 high-volume meta-only endpoint (update_meta_by_key) 에 한해 @model.save 대신 update_columns / update_all + 명시적 비동기 indexing 으로 분리해 동기 ES 콜백을 우회. MetableController#update_meta_by_key (app/controllers/concerns/metable_controller.rb:42-69) 의 흐름을 깨는 변경이므로 PR 전 design review 필요.

장기 개선 (재발 방지)#

• cupixworks-api 의 모든 Searchable 모델이 request thread 안에서 동기 ES 호출을 수행 (after_commit 콜백). high-throughput endpoint(*::*_meta* 류) 에서는 indexing 을 default async 로 두는 정책 변경 검토.
• APM 에서 trace.rails.request.duration{resource_name:Api::V1::PanosController#update_meta_by_key} 의 p99 SLO 를 설정해 outlier 가 cluster 화되기 전에 alert.

Monitoring#

다음 쿼리들을 release dashboard timeseries widget 에 추가해 동일 패턴 재발 시 즉시 잡는다 (writing-datadog-monitoring-queries 가이드에 따라 | stats, count by(...), threshold suffix 등 monitor-only 문법은 사용하지 않음).

평균/p95 latency 추이:

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

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

ES re-index 분기 빈도 (warn 로그 카운트):

sum:logs{service:cupixworks-api,@class:Pano,@function:_update_document,status:warn}.as_count()

해당 endpoint 의 요청 throughput (burst 윈도우 식별용):

sum:logs{service:cupixworks-api,action:update_meta_by_key,status:info}.as_count()

Risk Assessment#

• Risk level: low — 단일 occurrence, HTTP 200, downstream 데이터 손실 없음, 사용자 영향 없음.
• 예상 복잡도: trivial (모니터링 추가만) 또는 옵션 채택 시 standard (Searchable 콜백 동작 변경).