RCA: Api::V1::Admin::EditingsController#update — 14.6s latency

Overview#

What Happened#

2026-06-27 04:39 KST(UTC 19:39)에 production cupixworks-api (us-west-2)에서 PUT /api/v1/admin/editings/1192462 요청이 14,621.98ms 동안 실행되었다. 응답은 HTTP 200으로 정상 종료됐고, 요청은 Retool 어드민 도구가 editing의 state를 done으로 변경한 케이스다. 동일 cluster fingerprint의 발생 횟수는 1회. 동시간대(19:01–20:17 UTC) svc:cupixworks-api::unknown 인시던트가 진행 중이었다 (2026-06-26-svc-cupixworks-api--unknown-4).

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-27 04:39:19 KST (19:39:19.96 UTC) — PUT /api/v1/admin/editings/1192462 요청 시작 (duration 14621.98ms 기준 역산).
2. 2026-06-27 04:39:24 KST (19:39:24.532 UTC) — Editing 1192462: state ready → done 트랜지션 시작 (요청 시작 후 약 4.6초 경과).
3. 2026-06-27 04:39:28 KST (19:39:28.549 UTC) — FORCE_APPLY_ENTITIES_STATUSES after_transition: Capture 722909 bulk_operation! 호출.
4. 2026-06-27 04:39:30 KST (19:39:30.567 UTC) — Capture 상태 editing_ready → editing_done, refinement_state ready → queued.
5. 2026-06-27 04:39:30 KST (19:39:30.570 UTC) — CaptureInvoker#create_refinement, CreateCaptureRefinementJob 1156543 생성.
6. 2026-06-27 04:39:32 KST (19:39:32.571 UTC) — Facility 13474 reset_parent_cached_entity_updates 실행.
7. 2026-06-27 04:39:34 KST (19:39:34.576 UTC) — CreateCaptureRefinementJob#invoke_function (AWS Lambda Invoke) 호출.
8. 2026-06-27 04:39:34 KST (19:39:34.577 UTC) — Lambda status_code(202) 응답.
9. 2026-06-27 04:39:34 KST (19:39:34.586 UTC) — HTTP 200 응답 반환.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::Admin::EditingsController#update",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 14639,
  "max_ms": 14639,
  "sample_trace_id": "1305505309062459369"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-27 04:39 KST
• 최근 발생: 2026-06-27 04:39 KST
• 사용자 영향: Retool 어드민 사용자 1명이 editing 완료 시 14.6초 대기. 응답 자체는 성공(200). 동일 사용자/엔드포인트의 다른 호출은 0.2–2.1s 범위로 정상.

Root Cause Summary#

Admin이 editing의 state를 done으로 변경하는 단일 PUT /api/v1/admin/editings/:id 요청 안에서, refinement 타입 editing의 done 트랜지션이 연쇄 동기 callback 체인을 트리거한다. 체인은 (1) Editing 모든 editing_entities에 대한 done_state! 호출, (2) Capture 상태 editing_done 트랜지션 및 bulk_operation!, (3) Refinement 상태 queued 트랜지션, (4) CaptureInvoker#create_refinement로 CreateCaptureRefinementJob 생성, (5) 동기 AWS Lambda Invoke API 호출(전송은 invocation_type: Event지만 HTTP 호출 자체는 동기), (6) Facility reset_parent_cached_entity_updates 등 비-DB 작업을 포함한다. 로그 타임스탬프 기준 단계별 2–4초 gap이 누적되어 총 14.6s가 소요됐고, DB time은 1.8s에 불과해 latency의 대부분(12.8s)이 callback chain 내 외부 호출/카운트 갱신/락 대기에서 발생했다. 동시간대 cupixworks-api 서비스 전반에 latency 인시던트(2026-06-26-svc-cupixworks-api--unknown-4)가 진행 중이어서 외부 의존성 응답 지연이 callback chain의 누적 비용을 증폭시킨 것으로 보인다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/admin/editings_controller.rb:31 (#update)
• Repository: app/repositories/admin/editing_repository.rb:13-25 — @model.save! 호출
• State machine: app/models/concerns/statable/editing.rb:71-205 — done event의 다중 after_transition
• Capture state callback: app/models/concerns/refinementable.rb:55-57 — queued 트랜지션에서 run_capture_refinement 동기 호출
• Lambda invocation: app/jobs/create_capture_refinement_job.rb:36-75 — execute → invoke_function

Controller는 단순 위임이다:

def update
  @model = repository_instance.update(params)

  super
end

Repository도 save!만 호출하기 때문에 모든 비용은 모델 callback 체인에서 발생한다:

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

done 트랜지션의 after_transition은 4개가 등록되어 있고 모두 동기 실행된다:

after_transition from: any, to: FORCE_APPLY_ENTITIES_STATUSES do |model, transition|
  # Force to update editing entities state
  model.editing_entities.untrashed.each do |entity|
    # ...
    entity.public_send("#{transition.to_name}_state!")
  end
end

after_transition from: any, to: %i[done skipped] do |model, transition|
  if model.editing_type == 'refinement'
    capture = model.editing_entities.where(entity_type: 'Capture').includes(:entity).first&.entity
    capture.log_trace_event('preview_finished') if capture.present? && capture.respond_to?(:log_trace_event)
  end
end

after_transition from: any, to: :done do |model, transition|
  model.start_sitetrack
end

entity의 done_state!는 Capture의 refinement_state queued 트랜지션을 트리거하고, 이 트랜지션의 before_transition이 CaptureInvoker를 통해 AWS Lambda를 호출한다:

before_transition any => :queued do |model, transition|
  model.run_capture_refinement(model)
end

def run_capture_refinement(model)
  capture_invoker = CaptureInvoker.new(model: model, current_user: model.user, current_team: model.team)
  capture_invoker.create_refinement
end

Lambda 호출은 invocation_type: 'Event' (asynchronous on Lambda side) 이지만 Ruby 측 HTTP 호출 자체는 동기다:

def execute
  response = invoke_function
  Cupix::Logger.info("Refinement transform lambda status_code(#{response.try(:status_code)}) on #{self.class.name} #{id}", class: self.class.name, function: __method__)
rescue => e
  Cupix::Logger.warn("Refinement transform lambda failed, fallback to SQS on #{self.class.name} #{id}: #{e.message}", class: self.class.name, function: __method__)
  send_message
end

def invoke_function
  # ...
  response = client.invoke({
    function_name: refinement_service_name,
    invocation_type: 'Event',
    payload: payload.to_json
  })
end

기대 동작: refinement editing 완료 처리는 사용자 작업 흐름의 일부로 1초 내외에 응답해야 하고, Lambda invoke와 SQS 전송 같은 비-사용자-체감 외부 작업은 비동기(Sidekiq worker)로 분리되어야 한다.

실제 동작: 단일 HTTP 요청 안에서 (entity 업데이트 × N) + (Capture state 전이) + (refinement state 전이 + Lambda invoke) + (Facility cached-entity 갱신) + (start_sitetrack 가드) 가 모두 직렬 실행되어 step별 latency가 누적된다. 본 사례에서 DB(1.8s)는 정상 범위였으나, callback 단계 간 gap이 2–4s씩 발생했다.

Log Evidence#

사용한 Datadog 쿼리 — request_id로 trace 추출:

service:cupixworks-api @si_trace_id:ec55d518-9d55-4c9b-8cbc-267972102a8e

핵심 trace (오름차순):

2026-06-26T19:39:24.532Z  state has transitioned from ready to done on Editing 1192462
2026-06-26T19:39:28.549Z  update - id: 722909 - 722909                            (Capture#bulk_operation!)
2026-06-26T19:39:30.567Z  [Capture] state changed from editing_ready to editing_done
2026-06-26T19:39:30.567Z  refinement_state has transitioned from ready to queued on Capture 722909
2026-06-26T19:39:30.570Z  Refinement job is created for capture 722909. job_id: 1156543
2026-06-26T19:39:30.570Z  [Capture] create_refinement
2026-06-26T19:39:32.571Z  reset Facility (ID: 13474) cached entity updates
2026-06-26T19:39:32.574Z  [Capture] preview_finished
2026-06-26T19:39:32.574Z  Called for Editing 1192462 (editing_type: refinement)   (start_sitetrack)
2026-06-26T19:39:32.574Z  editing_type is not 'normal' for Editing 1192462
2026-06-26T19:39:32.574Z  Facility is not siteinsights for Editing 1192462
2026-06-26T19:39:32.574Z  StartSitetrackWorker not started for Editing 1192462 due to unmet conditions.
2026-06-26T19:39:34.576Z  Invoking refinement transform lambda for capture 722909
2026-06-26T19:39:34.577Z  Refinement transform lambda status_code(202) on CreateCaptureRefinementJob 1156543

Request 요약(원본 attributes):

{
  "@timestamp": "2026-06-26T19:39:34.586Z",
  "http": { "method": "PUT", "url_details": { "path": "/api/v1/admin/editings/1192462" }, "status_code": 200 },
  "duration": 14621.98,
  "db": 1801.45,
  "view": 0.09,
  "controller": "Api::V1::Admin::EditingsController",
  "action": "update",
  "params": { "state": "done", "id": "1192462", "fields": ["id", "state"] },
  "user_agent": "Retool/2.0",
  "user": { "id": 37822, "email": "eve.kim@cupix.com", "team": { "id": 133 } },
  "tenant": "cupix"
}

단계별 gap (callback chain 누적 비용):

동시간대 latency 인시던트 (status-board):

{
  "id": "2026-06-26-svc-cupixworks-api--unknown-4",
  "scope": "svc:cupixworks-api::unknown",
  "title": "cupixworks-api service degraded",
  "status": "open",
  "started_at": "2026-06-26T19:01:37.996Z",
  "last_event_at": "2026-06-26T20:17:28.494Z"
}

같은 20분 윈도(19:30–19:50 UTC)에서 @duration:>5000인 요청이 30건 이상 관찰됨 (PanosController#bulk, CapturesController#update 등 다양). 즉 본 cluster의 14.6s는 특정 endpoint 단독 회귀가 아니라 서비스 전반 latency 스파이크 와중에 callback chain이 증폭된 결과로 해석된다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 사용자 경험상 14s 단일 요청은 명백히 비정상이지만, 본 cluster는 단일 발생이고 응답은 성공이다. 즉시 코드 변경 없이, 동시간대의 service-wide latency 인시던트 (2026-06-26-svc-cupixworks-api--unknown-4) 해소를 우선 확인할 것 — 인시던트 페이지 링크: <DOCS_SITE_URL>/status/2026-06-26-svc-cupixworks-api--unknown-4.
• 재발 모니터링: Api::V1::Admin::EditingsController#update p95/p99 alert (아래 Monitoring 참조).

단기 개선 (1주 이내)#

• app/models/concerns/refinementable.rb:55-57 before_transition any => :queued 의 run_capture_refinement를 비동기 worker로 이관. 현재 CreateCaptureRefinementJob#run (app/jobs/create_capture_refinement_job.rb:28-34) 은 동기 execute (AWS Lambda Invoke) 를 수행하므로, Sidekiq worker로 enqueue만 하고 실제 invoke는 worker에서 실행하는 구조로 전환. Lambda 호출 자체는 1ms로 빠르지만, payload 준비/session 조회 등 부수 작업이 요청 경로에 남아있어 분리가 합리적이다.
• app/models/concerns/statable/editing.rb:141-153 FORCE_APPLY_ENTITIES_STATUSES 의 editing_entities.untrashed.each 루프를 entity 수에 비례한 비용으로 분석 — entity 수가 많은 editing에서는 응답 시간이 entity 수에 선형 증가. 필요 시 bulk update 또는 비동기 분리 검토.
• app/models/concerns/statable/editing.rb:172-174 after_transition ... model.start_sitetrack 는 가드 분기 (editing_type != 'normal' 등) 가 모두 동기 로깅을 수반한다. refinement 케이스는 곧바로 빠져나오므로 비용은 작지만, 향후 가드 추가 시 비동기화 고려.

장기 개선 (재발 방지)#

• State machine after_transition 으로 외부 시스템(Lambda, SQS, ES 인덱싱) 을 직접 호출하는 패턴 일반화 — 모든 외부 호출은 callback에서 worker enqueue로 통일하는 가이드라인 수립 및 점진적 적용.
• Admin 엔드포인트 SLO 정의 (예: p95 ≤ 2s, p99 ≤ 5s) 와 위반 시 자동 alert.
• service-wide latency 인시던트(svc:cupixworks-api::unknown) 의 근본 원인 추적 (별도 RCA) — 본 cluster는 그 인시던트의 한 단면일 가능성이 높다.

Monitoring#

• p95/p99 latency timeseries (resource 기준):

avg:trace.rack.request.duration.by.resource_service.95p{service:cupixworks-api,resource_name:api::v1::admin::editingscontroller#update}

• 5초 초과 update 발생 빈도:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::admin::editingscontroller#update,@duration:>5000}.as_count()

• refinement Lambda 호출 시간 (worker 측 이관 후):

avg:trace.aws.lambda.invoke.duration{function_name:cupix-refinement-transform-production}

• 서비스 전반 5xx + 느린 요청:

sum:trace.rack.request.errors{service:cupixworks-api}.as_count()

Risk Assessment#

• Risk level: low (occurrence_count=1, status 200, 직접 사용자 영향 1명, ongoing 광역 latency 인시던트의 한 단면)
• 예상 복잡도: standard (즉시 코드 변경 없음 + 단기 개선은 run_capture_refinement 비동기화 1건이 핵심)