RCA: Api::V1::EditingEntitiesController#update latency (avg 11634ms)

Overview#

What Happened#

2026-08-01 04:39 KST (production, us-west-2)에 PATCH /api/v1/editing_entities/1952673 요청 1건이 약 11.6초 소요된 것으로 APM 스팬에서 관측되었다. Datadog access log 상 HTTP 200 으로 정상 응답했으며 exception 은 발생하지 않았다. 클러스터는 error 가 아니라 latency 유형이며, 지금까지 1회 관측되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-08-01 04:39:27 KST — PATCH /api/v1/editing_entities/1952673 요청 시작 (Datadog APM 스팬 duration=11634ms 로 역산).
2. 2026-08-01 04:39:40 KST — 동일 요청 access log 에 [200] PATCH /api/v1/editing_entities/1952673 로 기록되어 정상 응답 확인.
3. 이후 2시간 반 동안 — 동일 resource 에 대한 추가 latency 클러스터 미관측 (service:cupixworks-api "EditingEntitiesController#update" 최근 3일 검색에서 이 건만 지연으로 잡힘).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::EditingEntitiesController#update",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11634,
  "max_ms": 11634,
  "sample_trace_id": "1954241260727965413"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-08-01 04:39 KST
• 최근 발생: 2026-08-01 04:39 KST

사용자 영향은 개별 요청 1건이 약 11.6초 지연된 수준이며, 응답은 성공(200)했다. 반복 발생하지 않았으므로 현재까지는 일시적 slow request 이다.

Root Cause Summary#

Api::V1::EditingEntitiesController#update 는 EditingEntityRepository#update → @model.save! 로 이어지며, 저장 시점에 Statable::EditingEntity 의 state machine 이 after_transition any => :ready 등을 통해 Finalization::EditingEntity#assign_editing_to_editing_entity 콜백을 호출한다. 이 콜백은 SQA geo grouping, _stamp_editing_id_on_elements, _absorb_capture_meta_from_victims, 다수의 BulkPartialIndexWorker/BulkPartialSaveJsonToFileWorker enqueue 를 포함하는 무거운 동기 경로이며, ActiveRecord::LockWaitTimeout/Deadlocked 시 최대 3회, base delay 10초(10 → 20 → 40 s exponential backoff) 로 sleep 후 retry 하도록 구현되어 있다. 이번 요청의 11.6초는 이 콜백 내 락 대기/재시도 또는 대량 ElementTrace 스캔 중 하나가 원인일 가능성이 가장 높다. 단, span 내부 breakdown 이 로그로 남지 않아 정확한 hot spot 은 미확인 (uncertain — needs verification).

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/editing_entities_controller.rb:19
• Repository update: app/repositories/editing_entity_repository.rb:9
• Base repository setup: app/repositories/base_repository.rb:131
• 저장 시 콜백 fan-out: app/models/concerns/statable/editing_entity.rb:53 (state_machine after_transition → ready)
• 무거운 동기 콜백 본체: app/models/concerns/finalization/editing_entity.rb:16
• Retry with sleep: app/models/concerns/finalization/editing_entity.rb:20-34
• Failure candidate 1 (락 대기): app/models/concerns/finalization/editing_entity.rb:23 (LOCK_RETRY_BASE_DELAY * (2**(retries - 1)) = 10s/20s/40s)
• Failure candidate 2 (대량 stamp): app/models/concerns/finalization/editing_entity.rb:409-457

def update
  @model = repository_instance.update(params)

  super
end

def update(params = {})
  super

  set_parameters(params)

  begin
    @model.save!
  rescue StandardError => e
    raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
  end

  @model
end

@model.save! 는 상태 변경이 포함되었을 경우 state_machine 의 after_transition any => :ready 를 통해 assign_editing_to_editing_entity 를 동기 실행한다.

after_transition any => :ready do |model, transition|
  model.set_editing_ready_at(transition.from)
  model.run_ready_state_callback
end

def assign_editing_to_editing_entity
  retries = 0
  begin
    _do_assign_editing_to_editing_entity
  rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e
    retries += 1
    if retries <= LOCK_RETRY_MAX_ATTEMPTS
      delay = LOCK_RETRY_BASE_DELAY * (2**(retries - 1))
      Cupix::Logger.warn("Lock timeout on editing assign, retry #{retries}/#{LOCK_RETRY_MAX_ATTEMPTS}",
                         class: self.class.name, function: __method__,
                         entity: { id: entity&.id, type: entity_type }, delay: delay)
      sleep(delay)
      retry
    else
      Cupix::Logger.error('Lock timeout on editing assign, max retries exceeded',
                          class: self.class.name, function: __method__,
                          entity: { id: entity&.id, type: entity_type })
      raise
    end
  end
end

이 재시도 경로 하나만 발동해도 사용자 요청은 최소 10초 blocking. 11.6초 총 시간과 잘 부합한다.

def _stamp_editing_id_on_elements(editing)
  et_rows = ::ElementTrace.where(task_id: entity.id, purpose: ::Cupix::EditingSplitService::PURPOSE_STATUS_UPDATE).pluck(:id, :record_id)
  # ...
  eligible_et_ids.each_slice(STAMP_BATCH_SIZE) { |batch| ::ElementTrace.where(id: batch).update_all(editing_id: editing.id) }
  element_ids = ::ElementTrace.where(id: eligible_et_ids).distinct.pluck(:element_id)
  element_ids.each_slice(STAMP_BATCH_SIZE) { |batch| ::Element.where(id: batch).update_all(editing_id: editing.id) } if element_ids.any?

  eligible_et_ids.each_slice(1000) do |slice|
    BulkPartialIndexWorker.perform_async('ElementTrace', slice, { 'editing_id' => editing.id })
    BulkPartialSaveJsonToFileWorker.perform_async('ElementTrace', slice, { editing_id: editing.id }.to_json)
  end

기대 동작: EditingEntity#update 는 부분 필드(예: state, category, level 등) 를 갱신하고 곧바로 200 을 반환. 실제 동작: state 가 ready 로 전이되었거나 SQA geo grouping 이 활성화된 대량 ElementTrace 를 가진 entity 였다면, 저장 트랜잭션 안에서 위 콜백이 실행되며 락 대기 또는 다량의 batch update + Sidekiq enqueue 로 지연이 누적된다.

Log Evidence#

Datadog 쿼리 (재현):

service:cupixworks-api "EditingEntitiesController#update"

기간: 2026-07-31 18:30Z ~ 20:30Z (해당 인시던트 전후 2시간).

관측된 access log — 정상 200 응답이지만 span duration 은 11.6s:

2026-08-01 04:39:40 KST  info  [200] PATCH /api/v1/editing_entities/1952673 (Api::V1::EditingEntitiesController#update)

동일 endpoint 의 최근 3일 완료 로그 30건 스캔 결과, 대부분은 access log 만 남고 body 스팬 내부 breakdown 은 확인 불가. 11.6s 급 지연은 이 1건이 유일 (sample_trace_id=1954241260727965413).

Query: service:cupixworks-api "1954241260727965413"
Window: 2026-07-31T18:00Z .. 2026-07-31T21:00Z
Result: 0 logs

Trace ID 자체는 로그에 부착되어 있지 않아 span 상세는 APM UI (제공된 Datadog URL) 에서만 확인 가능하다. LOCK_RETRY_MAX_ATTEMPTS 초과 시 남았을 Cupix::Logger.error('Lock timeout on editing assign, max retries exceeded', ...) 도 미검출 → 락 재시도가 임계치 이내에서 성공했거나, 애초에 락 대기가 원인이 아닐 가능성도 존재.

Status board 확인 결과: 해당 클러스터는 svc:cupixworks-api::unknown scope 에 속하나 활성 인시던트는 없다. 최근 관련 인시던트(2026-07-30, 2026-07-29, 2026-07-25)는 모두 이미 resolved 이며 별도 클러스터군이다.

scope: svc:cupixworks-api::unknown
active: null
recent: 3 resolved incidents (unrelated cluster ids)

Hypotheses Considered#

Root cause 후보는 H1 과 H2 이며 둘 중 하나로 좁힐 결정적 증거(warn 로그 또는 APM span breakdown)가 이번 조사 창에서 잡히지 않았다. 두 후보 모두 콜백 fan-out 동기 실행이 근본 원인이라는 점에서는 일치한다.

Fix Recommendation#

즉시 조치 (Critical)#

해당 클러스터는 1건짜리 latency 이므로 즉시 코드 수정은 불필요하다. 대신 다음 관측 강화만 수행한다.

• app/models/concerns/finalization/editing_entity.rb:24, 30 의 Cupix::Logger.warn/error 호출이 Datadog @class/@function 태그로 인덱싱되도록 로거 사용 규약을 재확인 (이번 조사에서 이 warn 로그가 검색되지 않은 이유가 태깅 누락인지 실제 미발생인지 구분 불가).

단기 개선 (1주 이내)#

Api::V1::EditingEntitiesController#update 의 p95/p99 지속 관측을 위한 모니터 세팅:

• Datadog APM 에서 resource:Api::V1::EditingEntitiesController#update 에 대해 span-level tag (callback.name=assign_editing_to_editing_entity, sqa_geo=true|false, retries=n) 를 남기도록 Finalization::EditingEntity 콜백에 Datadog::Tracing.trace 명시 계측 추가.
• 재시도 delay(현재 10/20/40s) 를 사용자 요청 경로에서 감내하기에 지나치게 길다. 재시도 자체는 유지하되, synchronous? 판정에 따라 콜백 전체를 background worker(AssignEditingWorker) 로 위임하는 옵션 검토. 근거: assign_editing_to_editing_entity 는 이미 다수 BulkPartial*Worker 를 enqueue 하는 fire-and-forget 형태이므로 최상위도 비동기화 여지가 큼 (finalization/editing_entity.rb:437-443).

장기 개선 (재발 방지)#

• state_machine after_transition 콜백에 무거운 fan-out 을 두는 패턴 전반 재검토. Ready 상태 진입 시 요청 응답 시간과 무관하게 처리되어야 하는 항목(elastic index, bulk save json, capture meta 흡수)은 모두 워커로 분리.
• SQA geo grouping 경로(_stamp_editing_id_on_elements, _absorb_capture_meta_from_victims, _trash_empty_victim_task_editing_entities) 는 대량 ElementTrace 를 다루므로 요청 스레드에서 벗어나야 함. 별도 job 으로 이관 후 Api::V1::EditingEntitiesController#update 응답을 202 Accepted + resource_url 로 전환하는 것도 API 계약 상 검토 가치 있음 (프론트엔드 조율 필요 — 자동 반영 대상 아님).

Monitoring#

Release dashboard 에 붙일 수 있는 timeseries widget 쿼리 예시:

• Api::V1::EditingEntitiesController#update p95 latency:

p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::editingentitiescontroller#update}

• 동일 resource 요청 rate:

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

• editing assign 콜백 락 재시도 발생 건수 (계측 추가 후):

sum:logs.hits{service:cupixworks-api,@class:finalization\/editingentity,@function:assign_editing_to_editing_entity,status:warn}.as_count()

• 3s 초과 slow request 개수:

sum:trace.rack.request{service:cupixworks-api,resource_name:api::v1::editingentitiescontroller#update,@duration:>3000000000}.as_count()

알림 임계치 예시: p95 > 3s 가 15분 이상 지속되면 warning, p95 > 8s 이면 critical.

Risk Assessment#

• Risk level: low — 1건 발생, HTTP 200 정상 응답, 사용자 영향 국소적.
• 예상 복잡도: standard — 코드 수정 없이 관측 계측 추가와 콜백 비동기화 검토가 주된 작업.