RCA: Api::V1::AssetsController#update_meta_by_key (avg 11761ms, max 11928ms)

Overview#

What Happened#

2026-06-11 10:44 KST 무렵 cupixworks-api (us-west-2, production) 에서 PUT /api/v1/assets/{key}/meta/prop (Api::V1::AssetsController#update_meta_by_key) 요청 2건이 평균 11.76초, 최대 11.93초로 비정상적으로 길게 처리되었다. 두 요청 모두 HTTP 200으로 성공했으나 같은 1분 창의 다른 동일 엔드포인트 요청들 (수십 ms ~ 수 백 ms) 대비 3050배 느렸다. 동일 시각대에 capture 후처리 클라이언트가 같은 엔드포인트로 다수의 Asset prop 메타 업데이트를 직렬로 보내고 있었으며, 그 중 두 건만 12초 가까이 지연된 것으로 관측된다.

Quick Facts#

Affected Teams#

영향 범위는 같은 1분 창에서 발생한 2건으로 한정 확인되었다.

Timeline#

1. 2026-06-11 10:44:30 KST — Asset update_meta_by_key 요청들이 prop 키로 평균 수십~수백 ms 수준으로 정상 처리됨 (Datadog logs).
2. 2026-06-11 10:44:50 KST — 첫 번째 slow trace 시작 (cluster first_seen 01:44:50.003Z UTC).
3. 2026-06-11 10:45:03 KST — Asset tuidvugxg8kr PUT 응답 [200] (Datadog log timestamp 01:45:03.052Z UTC) — 직전 정상 요청과 ~12s gap.
4. 2026-06-11 10:45:11 KST — Asset 87m1m2az9pcm PUT 응답 [200] (Datadog log timestamp 01:45:11.067Z UTC) — 다시 ~8s gap.
5. 2026-06-11 10:45:20 KST — 클러스터 last_seen (01:45:20.205Z UTC).
6. 2026-06-11 10:45:54-58 KST — 동일 환경에서 Pano/Pointcloud/Annotation _update_document 가 NotFound - attributes_in_database warn 다수 출력 (searchable.rb:108). Asset 엔드포인트와 직접 인과관계는 미확인이지만 같은 시간대 동일 인덱스 경로의 부하 신호.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::AssetsController#update_meta_by_key",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 11761,
  "max_ms": 11928,
  "sample_trace_id": "7735713525070468720"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-06-11 10:44:50 KST
• 최근 발생: 2026-06-11 10:45:20 KST
• 사용자 영향: 직접 에러는 아니며 두 요청 모두 200 성공. 다만 12초 응답은 capture 업로드 후처리 클라이언트의 throughput 을 떨어뜨리고, 클라이언트 측 타임아웃이 짧을 경우 retry 폭증을 유발할 수 있다.

Root Cause Summary#

Revision 2 에서 Datadog APM /api/v2/spans/events/search 로 trace span 분해를 수행한 결과, 본래 의심하던 콜백 체인(Searchable / EntityIndexable / AssetSerializer N+1)은 주된 원인이 아님으로 판명되었다. slow 요청 두 건의 실제 trace breakdown 은 모든 instrumented 비용(MySQL · Redis · Elasticsearch · HTTP)을 합쳐도 최대 700 ms 미만이며, 응답시간의 대부분은 두 종류의 계측되지 않은 gap 으로 채워져 있다 — (a) 첫 번째 요청은 UPDATE assets SET meta = ? (90 ms) 와 COMMIT (29 ms) 사이에 약 7.95 초 동안 어떤 span 도 발생하지 않은 구간이 존재하고, (b) 두 번째 요청은 COMMIT 직후부터 다음 rails.cache GET 까지 약 6.56 초 의 무계측 구간이 존재하며, 두 요청 모두 인증/세션/Asset 로딩 단계(action_controller 진입 전)에 추가로 1~3 초의 누적 gap 이 보인다. 동일 trace 의 host (i-0a026d499fb305739, r6a.xlarge, 4 vCPU) 메트릭은 같은 분에 CPU user 평균 92.6 % / 최대 94.2 %, load 1m 평균 5.9, system.mem.pct_usable 평균 3.3 % / 최대 4.7 % 로, CPU 와 사용 가능 메모리가 모두 거의 소진된 상태였고, 같은 호스트의 다른 endpoint (Api::V1::PanosController#create / #check_uploading, Pointclouds#check_uploading 등) 다수가 같은 시간대에 8~23 초의 응답시간을 기록했다. 따라서 두 slow update_meta_by_key 요청은 엔드포인트 고유의 결함이 아니라, 호스트 자원 포화 (CPU 컨텐션 + 사용 가능 메모리 부족) 로 인한 Ruby GVL/GC 일시 정지가 트랜잭션 내부와 callback 직렬화 사이에 끼어들어 발생한 stop-the-world 형태의 tail-latency 로 결론짓는다. 콜백 체인은 평소 잘 동작하고 있으며, 같은 1분의 정상 PUT 요청들은 < 700 ms 로 처리되었다 — 이는 콜백이 아니라 호스트 상태가 결정 변수임을 보여준다.

Technical Analysis#

APM Trace Breakdown (Revision 2)#

Datadog APM /api/v2/spans/events/search 로 trace_id:7735713525070468720 의 span 트리를 추출하여 두 slow root span 을 분해했다.

Slow request #1 — span_id 2594706683030857309, total 11927 ms (root: rack.request)

01:44:50.003  rack.request                 [+0ms]    Api::V1::AssetsController#update_meta_by_key  ← root, 11927ms
01:44:50.004    mysql2 SELECT users (auth)   5ms
01:44:50.180    mysql2 SELECT sessions       6ms       ← +170ms gap before this
01:44:50.673    mysql2 SELECT users (id)    27ms       ← +486ms gap (auth middleware)
01:44:50.718    mysql2 SELECT teams         24ms
01:44:51.197    mysql2 SELECT assets agg.   26ms       ← +455ms gap
01:44:51.498    mysql2 SELECT child assets  18ms       ← +270ms gap
01:44:51.520    mysql2 SELECT storages      12ms
01:44:51.775    mysql2 SELECT workspaces    27ms       ← +243ms gap
01:44:52.574    rails.cache GET             11ms       ← +772ms gap
01:44:52.587    mysql2 SELECT facilities     5ms
01:44:52.934    rails.action_controller   8976ms       ← +333ms gap, action begins
01:44:52.935      mysql2 SELECT users        0ms
01:44:52.939      mysql2 SELECT captures   201ms
01:44:53.149      mysql2 UPDATE assets      90ms       ← actual meta write
01:44:53.239      [end of UPDATE]
                  ████████████████████████████████   ← +7.95s GAP — no spans, no DB, no Redis, no ES, no HTTP
01:45:01.192      mysql2 COMMIT             29ms       ← transaction commit (after_save / before_commit work happened in the gap)
01:45:01.762      rails.cache GET (×4)     ~120ms      ← render path / serializer cache
01:45:01.886      rails.cache SET            3ms
01:45:01.894      sidekiq.push (Save…JSON)   0ms       ← DataWareHouse::PartialJson enqueue
01:45:01.895      redis SADD/LPUSH           8ms       ← Sidekiq Redis push
01:45:01.910    [action_controller end]
01:45:01.930  [rack.request end]

Slow request #2 — span_id 4116797933824845398, total 11593 ms

01:45:20.205  rack.request               [+0ms]      Api::V1::AssetsController#update_meta_by_key  ← root, 11593ms
01:45:20.207    mysql2 SELECT users         5ms
01:45:20.222    mysql2 SELECT sessions     56ms
01:45:20.300    mysql2 SELECT users        12ms
01:45:20.544    mysql2 SELECT teams         3ms       ← +232ms gap
01:45:21.944    mysql2 SELECT assets agg.  20ms       ← +1397ms gap (auth/load)
01:45:22.207    mysql2 SELECT child assets  8ms
01:45:22.910    mysql2 SELECT workspaces   15ms
01:45:23.225    rails.cache GET (×4)      ~30ms
01:45:23.256    rails.action_controller  8534ms       ← action begins
01:45:24.495      mysql2 SELECT captures   41ms       ← +1239ms gap before captures SELECT
01:45:24.553      mysql2 UPDATE assets     26ms
01:45:25.130      mysql2 COMMIT            16ms       ← +551ms gap, then commit
                  ████████████████████████████████   ← +6.56s GAP after COMMIT — no spans
01:45:31.704      rails.cache GET          36ms       ← render path resumes
01:45:31.777      sidekiq.push              0ms
01:45:31.783    [action_controller end]
01:45:31.798  [rack.request end]

핵심 관측:

1. Instrumented span 합계는 ~700 ms 미만 (#1: SELECT/UPDATE/COMMIT/cache 합 ~440 ms; #2: ~340 ms). 나머지 11 초가 모두 unaccounted gap 이다.
2. 무계측 gap 은 두 군데에 큰 덩어리로 몰려 있다 — (a) action_controller 진입 전 인증/세션/리소스 로딩 단계(#1 약 2.9 s, #2 약 3.0 s 누적), (b) UPDATE 와 COMMIT 사이 또는 COMMIT 직후(7~8 s).
3. UPDATE assets 와 COMMIT 사이 7.95 s 구간에 ES HTTP span / Faraday span / 추가 mysql2 span 이 0 건 — 따라서 원래 가설이었던 Searchable._update_document 의 ES update HTTP 호출이 12 초 걸렸다는 시나리오는 직접 증거로 반박된다 (그 호출이 있었다면 http.request 또는 elasticsearch.query span 이 떴어야 한다).
4. 두 번째 요청의 COMMIT 직후 6.56 s gap 은 after_commit 콜백(_update_document, _entity_update_document, save_partial_json_to_file_as_updated) 이 실행되는 구간이다. 그 안에서도 ES/Redis/MySQL span 이 전혀 출력되지 않으므로 콜백들이 실제 외부 호출에서 막힌 것이 아니라, Ruby 인터프리터가 그 구간 동안 진행을 멈췄거나 (GC pause / GVL 대기) 매우 느리게 실행했음을 시사한다.

Host Resource Saturation Evidence#

같은 host (i-0a026d499fb305739, instance-type r6a.xlarge, 4 vCPU, AZ us-west-2b) 의 시스템 메트릭을 Datadog /api/v1/query 로 확인했다 (window: 2026-06-11T01:43:00Z – 01:47:00Z, 4분, 16 데이터포인트):

• 4 vCPU 인스턴스에서 user CPU 92.6 % + load 5.9 — CPU oversubscribed (load > vCPU). Puma worker 들이 GVL 을 두고 경쟁.
• mem.pct_usable 3 % — 사용 가능 메모리가 거의 소진. Ruby GC 가 자주 / 길게 트리거되며, OS page cache 압박으로 file/socket I/O 도 영향받을 수 있음. swap 은 0 (인스턴스에 swap 미구성).
• 같은 호스트의 다른 endpoint 도 같은 시간대에 다중 slow trace 발생 — service:cupixworks-api operation_name:rack.request host:i-0a026d499fb305739 @duration:>3000000000 검색 결과 5분 안에 30 건 이상이 hit, 그 중 다수가 8~23 초 범위:

23071ms  01:47:22  Api::V1::PanosController#create
22284ms  01:47:29  Api::V1::PointcloudsController#check_uploading
21261ms  01:47:27  Api::V1::PanosController#create
17164ms  01:47:30  Api::V1::PanosController#check_uploading
16703ms  01:47:29  Api::V1::PanosController#check_uploading
16701ms  01:47:29  Api::V1::PanosController#check_uploading
16002ms  01:47:39  Api::V1::PanosController#create
15576ms  01:47:41  Api::V1::PanosController#create
15297ms  01:47:35  Api::V1::PanosController#create
15056ms  01:47:42  Api::V1::PanosController#create
14781ms  01:47:36  Api::V1::PanosController#create
14546ms  01:47:42  Api::V1::PanosController#create
13813ms  01:47:43  Api::V1::PanosController#create
13204ms  01:47:42  Api::V1::PanosController#check_uploading
12974ms  01:47:39  Api::V1::PanosController#check_uploading
12958ms  01:47:44  Api::V1::PanosController#check_uploading
...

호스트 자원 포화는 update_meta_by_key 만의 문제가 아니며, 같은 박스 위의 모든 Rails 워크로드에 동시에 영향을 주고 있었다.

Code Path#

• Entry point: app/controllers/concerns/metable_controller.rb:42 (update_meta_by_key)
• Save trigger: app/controllers/concerns/metable_controller.rb:51 — @model.save
• Asset callbacks chain (after_commit on update):
  • app/models/concerns/searchable.rb:16 → _update_document
  • app/models/concerns/entity_indexable.rb:43 → _entity_update_document
  • app/models/concerns/data_ware_house/partial_json.rb:7 → save_partial_json_to_file_as_updated
• Render path: app/controllers/concerns/metable_controller.rb:65 (render_json 200, @model.meta[params[:meta_key]]) — Asset 본문 serialization 자체는 이 경로에서 호출되지 않으나, as_indexed_json 폴백은 AssetSerializer 를 사용

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
    # ... Cluster meta logging branch (Asset 에는 해당 없음)
  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: ...", ...)
  end
end

핸들러는 단순히 meta[key] 만 갱신 후 save 한다. 비용은 거의 전부 save 에 매달린 after_commit 들에서 발생.

def _update_document
  Cupix::Logger.debug('begin - _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   # full re-serialize
                   else
                     # changed-keys subset
                   end
                 else
                   attributes_in_database
                 end

    unless attributes.empty?
      results = __elasticsearch__.client.update(...)
    end
  else
    Cupix::Logger.warn('NotFound - attributes_in_database', ...)
    _index_document   # full re-index fallback (AssetSerializer 호출)
  end
rescue Faraday::TimeoutError, Elasticsearch::Transport::Transport::Error, StandardError
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

Asset 의 indexed fields 에는 meta 가 포함되어 있지 않다 (app/models/concerns/searchable/asset.rb:104-138). 따라서 meta 만 변경된 경우 changed-keys subset 이 비어 ES update 자체는 NO-OP 으로 빠르게 끝나야 한다. 그러나 같은 1분 창에 다른 모델(Pano 등) 에서 NotFound - attributes_in_database warn 이 다수 발생 — fallback _index_document (full re-index) 가 활성화되면 ES 호출 1회 + AssetSerializer 직렬화 비용이 더해진다.

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   # 매번 full payload 빌드
  )
rescue StandardError => e
  Cupix::Logger.error("Entity update error - #{e.message}", ...)
end

as_entity_indexed_json 은 매번 _entity_user (User where(id:).select 1쿼리), _entity_ancestry (team / workspace / facility / record / capture / level / bim / review / annotation_layer 각각 lookup 시도) 를 실행한다 (app/models/concerns/entity_indexable.rb:51-120). cache 인자가 없으므로 항상 실DB 조회. 이론상 매 save 마다 최대 9~10개의 ancestor 조회 + User 조회 + Facility lookup 이 실행된다.

def save_partial_json_to_file_as_updated(changes: nil, all_data: false)
  if $FORWARD_DATA_CHANGES != true
    return nil
  end
  if !all_data && changes.blank? && saved_changes.blank?
    return nil
  end
  save_partial_json_to_file_in_worker(operation: '(updated)', changes: changes || saved_changes,
                                      all_data: all_data, timestamp: current_timestamp)
end

save_partial_json_to_file_in_worker 는 Sidekiq enqueue (Redis push) 만 한다 — 정상이라면 < 10ms. Redis 지연 시 영향 가능.

attribute :child_assets do |model|
  model.child_assets.map do |asset|
    {
      id: asset.id, key: asset.key, parent_asset_key: asset.parent_asset&.key,
      asset_type: asset.asset_type, name: asset.name, description: asset.description,
      created_at: asset.created_at, updated_at: asset.updated_at,
      cover_urls: asset.cover_urls, thumbnail_urls: asset.thumbnail_urls,
      state: asset.state, cover_state: asset.cover_state,
      transcript_state: asset.transcript_state, meta: asset.meta
    }
  end
end

attribute :badges do |asset|
  if asset._associated_badges[:associated_resourcable_ids].present?
    # ...

AssetSerializer 가 _index_document 폴백 시 호출되며, 각 child_asset 마다 parent_asset/cover_urls/thumbnail_urls 추가 쿼리 — child 수에 비례해 시간이 늘어날 수 있는 N+1 패턴.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "/assets/" "update_meta_by_key"
  -f 2026-06-11T01:44:30Z -t 2026-06-11T01:45:30Z

같은 1분 창의 Asset PUT 응답 시각 분포 (모두 200) — 정상 수십 ms ~ 수 백 ms 간격으로 처리되다가 두 곳에서 ~12초/~8초 gap 이 보임:

2026-06-11T01:44:30.501Z  PUT /api/v1/assets/jeh0df58z7s/meta/prop   [200]
2026-06-11T01:44:34.607Z  PUT /api/v1/assets/cgei3by56ebo/meta/prop  [200]
2026-06-11T01:44:38.617Z  PUT /api/v1/assets/vgpmqd117452/meta/prop  [200]
2026-06-11T01:44:40.531Z  PUT /api/v1/assets/zaaw2v6clzy/meta/prop   [200]
2026-06-11T01:44:42.633Z  PUT /api/v1/assets/p6s91o3mmkx2/meta/prop  [200]
2026-06-11T01:44:46.552Z  PUT /api/v1/assets/ouv9nzpgyoc7/meta/prop  [200]
2026-06-11T01:44:49.030Z  PUT /api/v1/assets/7vzhggfpo9yk/meta/prop  [200]
2026-06-11T01:44:50.564Z  PUT /api/v1/assets/3qozzhjeklzp/meta/prop  [200]
2026-06-11T01:44:50.565Z  PUT /api/v1/assets/rsy3hl34hu7t/meta/prop  [200]
2026-06-11T01:45:03.052Z  PUT /api/v1/assets/tuidvugxg8kr/meta/prop  [200]   ← ~12s gap
2026-06-11T01:45:11.067Z  PUT /api/v1/assets/87m1m2az9pcm/meta/prop  [200]   ← ~8s gap

같은 capture 후처리에서 동일한 prop 페이로드 키셋이 사용되었음을 확인 (@class:Asset @function:update_meta_by_key):

2026-06-11T01:45:11.938Z  Meta updated by key: 'prop' - keys: ver|tm|wtm|rtm|quad|wquad|tethering_pano_id (Asset)
2026-06-11T01:45:31.973Z  Meta updated by key: 'prop' - keys: ver|tm|wtm|rtm|quad|wquad|tethering_pano_id (Asset)
2026-06-11T01:45:34.598Z  Meta updated by key: 'prop' - keys: ver|tm|wtm|rtm|quad|wquad|tethering_pano_id (Asset)
2026-06-11T01:45:38.607Z  Meta updated by key: 'prop' - keys: ver|tm|wtm|rtm|quad|wquad|tethering_pano_id (Asset)
2026-06-11T01:45:44.591Z  Meta updated by key: 'prop' - keys: ver|tm|wtm|rtm|quad|wquad|tethering_pano_id (Asset)

같은 시간 창에서 Pano/Pointcloud/Annotation _update_document 의 NotFound - attributes_in_database warn 이 다수 출력 — Searchable 폴백 경로(_index_document full re-index) 가 활발히 활성화되어 있었음:

2026-06-11T01:45:54.834Z  warn  NotFound - attributes_in_database  class=Pano       function=_update_document
2026-06-11T01:45:54.835Z  warn  NotFound - attributes_in_database  class=Pano
2026-06-11T01:45:54.872Z  warn  NotFound - attributes_in_database  class=Annotation
2026-06-11T01:45:55.993Z  warn  NotFound - attributes_in_database  class=Pano
2026-06-11T01:45:57.941Z  warn  NotFound - attributes_in_database  class=Pointcloud
2026-06-11T01:45:57.997Z  warn  NotFound - attributes_in_database  class=Pano

status:error 검색은 같은 창에서 0건, Faraday::TimeoutError / BulkIndexWorker 도 0건이었다 — ES 자체가 timeout 으로 실패한 것은 아니며, 폴백·콜백 누적의 누그러진(slow) 형태로 나타난 tail-latency 임을 시사.

Hypotheses Considered#

Fix Recommendation#

Revision 2: 근본 원인이 호스트 자원 포화로 재정의됨에 따라, 권장 사항도 콜백 코드 최적화에서 호스트 레벨 capacity / 메모리 / 가시성 강화로 재정렬되었다.

즉시 조치 (Critical)#

• 호스트 메모리 사용량 알람 도입 (또는 thresholds 점검): system.mem.pct_usable < 10 % 5 분 지속 시 PagerDuty/Slack 알람. 본 incident 호스트는 incident 시점에 사용 가능 메모리가 평균 3.3 % / 최대 4.7 % 이었으므로 사전 경고가 떴어야 한다. Datadog monitor 또는 Beanstalk 알람으로 즉시 추가 권장.
• 즉각적인 코드 변경은 권장하지 않는다 — APM 분해 결과 코드 결함이 아니라 호스트 capacity 이슈. 발생 건수 2 건, 모두 HTTP 200 성공.

단기 개선 (1주 이내)#

• EB 환경 capacity 검토: tesla-prod Beanstalk 환경의 instance type (r6a.xlarge, 4 vCPU / 32 GB) 이 정상 시간대의 부하 (195 req/min/host 평균, 317 req/min/host 최대) 와 콜백 직렬화 비용을 안정적으로 처리하는지 재평가. 현재 user CPU 가 90 % 이상으로 지속되는 박스가 존재한다면 (a) auto-scaling threshold 를 user CPU 70 % 또는 메모리 사용 가능 < 20 % 로 낮추거나, (b) Puma worker 수 / 인스턴스 수를 조정.
• APM custom span 으로 콜백 가시성 확보: _update_document / _entity_update_document / save_partial_json_to_file_* 를 Datadog::Tracing.trace('callback.…') 로 감싸서 trace flame graph 에서 무계측 gap 의 정체를 다음에는 직접 확인할 수 있게 한다 (이번에는 gap 안에 어떤 코드가 돌았는지 trace 만으로 확정 불가).
• GC / GVL 메트릭 수집: dd-trace-rb 의 profiling (DD_PROFILING_ENABLED=true) 또는 ruby.gc.* custom metric 을 활성화하여 GC stop-the-world 와 GVL wait 시간을 host 단위로 추적. 본 RCA 의 H6 (호스트 포화 → GC/GVL pause) 가설을 정량 검증할 수 있다.

장기 개선 (재발 방지)#

• Api::V1::AssetsController#update_meta_by_key 처리 시간 SLO: p95 < 1 s, p99 < 3 s 를 SLO 로 설정하고 위반 시 알람. (단, 호스트 단위 자원 포화로 인한 violation 은 endpoint 책임이 아니라 capacity 책임으로 분류하기 위해 system.cpu.user / system.mem.pct_usable 메트릭과 함께 본다.)
• Bulk meta update 엔드포인트 도입 검토: capture 후처리가 Asset 마다 PUT 을 직렬로 보내는 패턴은 호스트당 N 회의 콜백 누적을 강제한다 — 호스트가 자원 부족 상태일 때 특히 취약. 다수 Asset 에 prop 을 한 번에 갱신하는 bulk endpoint 가 있다면 ES 콜백을 bulk API 로 합칠 수 있다 (searchable.rb:170 bulk_operation 클래스 메서드 참고). 이는 본 incident 의 직접 원인 해결이 아니라 부하 자체를 줄여 자원 포화 임계 도달 시점을 늦추는 보조 조치.
• (보류) 콜백 N+1 제거 (EntityIndexable._entity_update_document, AssetSerializer): APM trace 에서 콜백 자체가 12 초 지연의 주된 원인이 아님이 확인되어 본 incident 의 처방으로는 우선순위 낮음. 다만 일반적인 효율 개선 차원에서는 여전히 유효 — 별도 백로그로 분리.

Monitoring#

추가/유지할 메트릭:

• Api::V1::AssetsController#update_meta_by_key 의 P95 / P99 latency
• 호스트 단위 system.cpu.user, system.load.1, system.mem.pct_usable (Revision 2: 본 incident 의 주요 신호)
• 같은 호스트의 다른 endpoint slow trace 동시 발생률 (host-level 포화 판별)
• 동일 시각대 Searchable warn (NotFound - attributes_in_database) 발생률 (보조 신호)

Datadog 쿼리 예시:

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

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::assetscontroller#update_meta_by_key} by {http.status_code}.as_count()

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:api::v1::assetscontroller#update_meta_by_key}.as_count()

sum:trace.rack.request{service:cupixworks-api,resource_name:api::v1::assetscontroller#update_meta_by_key,@duration:>5000000000}.as_count()

avg:system.cpu.user{service:cupixworks-api} by {host}

avg:system.mem.pct_usable{service:cupixworks-api} by {host}

Risk Assessment#

• Risk level: medium (Revision 2 에서 상향 — 단일 호스트의 자원 포화가 같은 박스의 다수 endpoint 를 동시에 8~23 초까지 늘어지게 만드는 현상이 같은 5분 안에서 30 건 이상 관측됨; 메모리 사용 가능 ~3 % 상태가 알람 없이 유지됨)
• 예상 복잡도: standard (코드 수정보다는 capacity/모니터링 측 변경 — auto-scaling threshold 조정, 메모리 알람 추가, dd-trace profiling 활성화)
• 두 건의 12 초 지연 자체는 200 성공이지만, 같은 호스트의 다른 endpoint 들이 동시에 늘어진 점에서 호스트 단위 사용자 경험 영향은 더 광범위했을 가능성 (uncertain — 클라이언트 측 timeout / retry 발생 여부는 본 RCA 범위에서 확인하지 않음).

Revision History#

Revision 2#

Feedback (2026-06-11): "datadog api 에서 apm 이나 trace 를 통해서 어떤것들 때문에 시간이 오래걸렸는지 확인해바" — APM trace 분해를 통해 어떤 구간/콜백이 실제로 시간을 잡아먹었는지 직접 확인 요청.

판정:

변경 사항:

• ## Root Cause Summary 재작성 — 콜백 누적 가설에서 호스트 자원 포화 가설로 결론 변경.
• ## Technical Analysis 에 ### APM Trace Breakdown (Revision 2) 새 subsection 추가 (두 slow root span 의 timeline 분해 + gap 표시).
• ## Technical Analysis 에 ### Host Resource Saturation Evidence 새 subsection 추가 (host 메트릭 표 + 같은 호스트 다른 endpoint slow trace 목록).
• ## Hypotheses Considered — H1 verdict 를 "Confirmed" → "Downgraded — 부분 기여 가능하나 주된 원인 아님" 으로 변경, H6 (host saturation) 추가 후 Confirmed 로 표시, H2/H3 의 evidence against 보강.
• ## Fix Recommendation 재정렬 — Critical 에 메모리 사용량 알람 추가, 단기 개선에 EB capacity 검토 / APM custom span / GC·GVL 메트릭 활성화 추가, 콜백 N+1 제거는 "보류 / 별도 백로그" 로 강등.
• ## Monitoring 에 host 단위 CPU / 메모리 쿼리 추가.
• ## Risk Assessment risk level 을 low → medium 으로 상향, 단일 호스트 영향 범위가 endpoint 단위가 아닌 호스트 위 모든 워크로드라는 점을 반영.

추가 조사 내용:

• Datadog APM Spans Search API (POST /api/v2/spans/events/search) 로 trace 분해 — 185 + 167 spans, slow root span 4 건 식별 (avg 5 s 이상).
• Datadog Metrics Query API (GET /api/v1/query) 로 host 단위 시스템 메트릭 (system.cpu.user, system.load.1, system.mem.pct_usable, system.swap.used, sum:trace.rack.request.hits.as_count()) 확인.
• Datadog APM Spans Search 로 같은 호스트 (host:i-0a026d499fb305739) 의 동시 slow trace 30 건 식별 — host-level saturation 확정 근거.
• (의도적으로 새로 탐색하지 않은 영역) tesla 레포의 searchable.rb / entity_indexable.rb / asset_serializer.rb — 기존 Revision 1 의 코드 분석은 그대로 유지하되, "주된 원인 아님" 으로 재분류. 추가 코드 변경 권장 없음.