RCA: Api::V1::EditingsController#update latency (avg 23.6s)

Overview#

What Happened#

2026-06-24 23:00 KST 경 production cupixworks-api에서 PATCH /api/v1/editings/1186395 요청이 23.6초 동안 처리되었다. APM이 단일 trace (4152316883185863783)를 latency 클러스터로 분류했고, 같은 endpoint의 다른 호출(13:57:30/33 등)은 1초 미만으로 정상 종료되었다. 응답 자체는 HTTP 200이며 에러는 발생하지 않았다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-24 23:00:08 KST — cluster.first_seen (Datadog APM 기준 요청 시작 시각, response 시각에서 duration을 역산해 도출)
2. 2026-06-24 23:00:09 KST — Editing 1186395 state machine before_transition: editing → done 로그 기록 (save! 시작 직후)
3. 2026-06-24 23:00:23 KST — start_sitetrack after_transition 콜백 진입 — 위 단계와 약 14초 간격
4. 2026-06-24 23:00:23 KST — Facility is not siteinsights 분기 → StartSitetrackWorker not started ... due to unmet conditions 종료
5. 2026-06-24 23:00:32 KST — [200] PATCH /api/v1/editings/1186395 응답 — start_sitetrack 종료와 약 9초 간격

Error Log#

Datadog Logs

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

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-24 23:00 KST
• 최근 발생: 2026-06-24 23:00 KST

발생 빈도 1회의 단발성 outlier로, 같은 endpoint의 인접 호출(13:57:30Z, 13:57:33Z UTC)은 1초 미만에 정상 응답했다. 사용자 체감 지연만 있고 데이터 손실은 없다.

Root Cause Summary#

Api::V1::EditingsController#update는 EditingRepository#update 내부에서 @model.save!를 호출하고, 이 save가 editing → done 상태 전이의 모든 state_machine 콜백 (LogEditingStateWorker.perform_async, FORCE_APPLY_ENTITIES_STATUSES 전파, start_sitetrack, sync_review_completion 등)을 요청 thread 내에서 동기적으로 실행한다. 본 호출에서는 (a) before_transition 로그(23:00:09)부터 start_sitetrack 진입(23:00:23)까지 약 14초, (b) start_sitetrack(23:00:23)부터 HTTP 200 응답(23:00:32)까지 약 9초의 공백이 관찰되었고, 이 구간의 가시 로그가 부재하다. 인접 시간대 평균 요청 시간이 1초 내외인 점, start_sitetrack이 Facility is not siteinsights로 worker 큐잉 없이 빠르게 종료된 점, error/warn 로그가 없는 점을 종합하면 본 outlier는 코드 결함(예: nil 참조, 루프 폭주)이 아니라 save! 트랜잭션 또는 state_machine 콜백 체인 안의 DB/Elasticsearch 호출이 일시적으로 stall한 결과로 판단된다. 같은 서비스에서 같은 날 다수의 단발성 latency 클러스터(FacilitiesController#share 33s, Admin::TeamsController#create 18s)가 흩어져 발생한 패턴도 endpoint-국소가 아닌 인프라 측 일시 지연 가설을 뒷받침한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/editings_controller.rb:22
• Save site: app/repositories/editing_repository.rb:17
• 상태 전이 콜백 체인: app/models/concerns/statable/editing.rb:83-205
• "Slow span" 후보 구간: 위 콜백 체인 내부의 DB write / Elasticsearch indexing / LogEditingStateWorker.perform_async (Sidekiq enqueue → Redis)

Controller update action — repository를 호출하고 부모 Api::V1::ApiController#update로 위임한다.

def update
  @model = repository_instance.update(params)

  super
end

Repository update — 모든 비용은 @model.save!에 집중되어 있다. 외부 호출 없는 단순 코드지만 state_machine 콜백이 save 내부에서 모두 실행된다.

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

before_transition — LogEditingStateWorker.perform_async (Sidekiq enqueue, Redis 왕복) + model.build_event(...) (DB write) + model.state_updated_at = DateTime.now + stat_transition. 본 trace의 첫 로그 (23:00:09)가 이 블록 안에서 찍힌다.

before_transition do |model, transition|
  Cupix::Logger.info("state has transitioned from #{transition.from} to #{transition.to} on Editing #{model.id}",
                     class_name: self.class.name,
                     function: __method__, ...)

  if transition.from != transition.to
    ...
    if model.respond_to?(:build_event)
      model.build_event(
        action: 'update',
        reason: "editing_state_#{transition.to_name}",
        send_ios_notification: _send_ios_notification
      )
    end

    LogEditingStateWorker.perform_async(model.id, transition.from, transition.to, model.editor_id)
    model.state_updated_at = DateTime.now if model.respond_to?('state_updated_at=')
    model.stat_transition(transition.from, transition.to) if model.respond_to?('stat_transition')
  ...
  end
end

FORCE_APPLY_ENTITIES_STATUSES는 [:ready, :holding, :skipped, :done]을 포함한다. :done 전이 시 모든 editing_entities.untrashed에 대해 done_state!를 호출하여 각 entity의 state_machine을 다시 돌린다. 본 trace에서는 update editing_entity state from ... 형식의 로그가 잡히지 않았으므로 — 대상 entity가 없거나 entity가 이미 done 상태에 있어 transition이 일어나지 않은 것으로 추정된다. 그러나 entity가 적재되더라도 transition 자체는 발생하지 않을 수 있다 (state_machine은 from==to를 처리한다).

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|
    Cupix::Logger.info("update editing_entity state from #{entity.state} to #{transition.to_name}. ...")

    entity.public_send("#{transition.to_name}_state!")
  end
end

start_sitetrack — Facility is not siteinsights로 일찍 종료. 빠른 분기지만 진입까지 14s가 소요됐다.

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

def start_sitetrack
  Cupix::Logger.info("Called for Editing #{self.id} (editing_type: #{self.editing_type})", ...)
  sitetrack_startable = true

  if self.editing_type != 'normal'
    Cupix::Logger.info("editing_type is not 'normal' for Editing #{self.id}", ...)
    sitetrack_startable = false
  end

  facility = self.facility
  if facility.nil?
    Cupix::Logger.info("Facility is nil for Editing #{self.id}", ...)
    sitetrack_startable = false
  elsif !facility.siteinsights?
    Cupix::Logger.info("Facility is not siteinsights for Editing #{self.id}", ...)
    sitetrack_startable = false
  end
  ...
end

기대 동작: 상태 전이는 보통 1초 안에 끝난다 (인접 호출에서 13:57:30→13:57:33 사이 두 번의 PATCH 완료가 그 증거). 실제 동작: 단일 요청에서 before_transition 로그(23:00:09) ↔ start_sitetrack(23:00:23) ↔ HTTP 200(23:00:32) 사이에 가시 로그가 없는 두 개의 큰 공백 (14s, 9s) 이 관찰됐다. 두 공백 모두 DB 트랜잭션 commit / Searchable callback (Elasticsearch reindex) / Sidekiq enqueue(Redis) 중 한 곳에서 일어났을 가능성이 가장 높지만, info 레벨로 더 잘게 trace되어 있지 않아 정확한 지점은 본 trace 단독으론 단정할 수 없다 — uncertain — needs verification (APM span 상세 또는 debug log 필요).

Log Evidence#

Datadog log search query:

service:cupixworks-api "1186395"
time: 2026-06-24T13:50:00Z .. 2026-06-24T14:05:00Z

slow trace에 대응하는 5개 로그 전체 (시각 오름차순, 원문):

2026-06-24T14:00:09.216Z  info  state has transitioned from editing to done on Editing 1186395
2026-06-24T14:00:23.231Z  info  Called for Editing 1186395 (editing_type: normal)
                                function=start_sitetrack
2026-06-24T14:00:23.231Z  info  Facility is not siteinsights for Editing 1186395
                                function=start_sitetrack
2026-06-24T14:00:23.231Z  info  StartSitetrackWorker not started for Editing 1186395 due to unmet conditions.
                                function=start_sitetrack
2026-06-24T14:00:32.529Z  info  [200] PATCH /api/v1/editings/1186395 (Api::V1::EditingsController#update)

비교용 — 같은 endpoint의 인접 정상 호출 (Editing 1185428):

2026-06-24T13:57:29.119Z  info  state has transitioned from holding to ready on Editing 1185428
2026-06-24T13:57:30.276Z  info  [200] PATCH /api/v1/editings/1185428  ← 약 1.2s
2026-06-24T13:57:33.118Z  info  [200] PATCH /api/v1/editings/1185428
2026-06-24T13:57:33.730Z  info  state has transitioned from ready to editing on Editing 1185428

서비스 평균 응답 시간 (Datadog metric avg:trace.rack.request.duration{service:cupixworks-api}, 13:30–15:30Z, interval 60s, 단위 초)은 대부분 0.5–1.5초 구간이고 14:00 직전 후 단일 spike도 평균값으로는 1.4초 수준 — 23초 outlier가 단일 요청의 spike임을 확인.

... 0.621353, 0.654199, 0.743816, 0.616478, 0.610284, 0.616644, 0.667117, 0.671612, 0.622139, 0.637381, 0.646707, 0.648214, 0.717384, 0.641942, 0.541728, 0.563188, 0.553034, 0.496511, 0.505689, 0.544983, 0.732632, 0.664691, 0.591182, 0.610413, 0.562875, 0.55583, 0.713276, 0.808308, 0.954515, 1.090828, 1.173045, 1.084102, 1.390574, 1.403886, 1.451832, 1.570316, 1.194198, 1.454334, 1.222804, 1.125905, 1.411234, 1.073951

같은 날 같은 서비스에서 비슷한 단발성 latency 클러스터가 다수 발생했다 (status-board incident 2026-06-24-svc-cupixworks-api--unknown-1, 11 cluster):

ee31e7aa  Api::V1::Admin::TeamsController#create    18,082 ms   12:40:16Z
277b768e  Api::V1::FacilitiesController#share       avg 33,254 / max 83,140 ms  10:23:45Z
2ca0d832  Api::V1::EditingsController#update        23,603 ms   14:00:08Z   ← 본 클러스터
... 등

서로 다른 endpoint들이 동일 패턴으로 단발성 outlier를 만든 점은 endpoint-국소 결함보다는 인프라/공유 자원 측 일시 지연 가설을 뒷받침한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

별도 코드 변경 없음. 본 cluster는 1회성 단발 outlier이며 인접 시간대 평균 응답이 정상 범위. status-board incident 2026-06-24-svc-cupixworks-api--unknown-1 이 이미 resolved 상태이므로 추가 운영 조치는 불필요하다.

같은 클러스터의 재발 가능성을 줄이기 위한 가장 효과적 1차 조치는 다음 두 가지다 (선택 적용, 코드 작성은 별도 작업):

• app/repositories/editing_repository.rb:17 의 @model.save!가 호출하는 state_machine 콜백 중 요청 thread의 critical path 밖으로 옮길 수 있는 작업을 분리하는 방향 검토:
  • LogEditingStateWorker.perform_async(statable/editing.rb:102) 는 이미 비동기지만 enqueue 자체가 Redis stall에 묶이면 콜백 thread를 잡는다 — Sidekiq Redis pool/health 모니터링 강화.
  • FORCE_APPLY_ENTITIES_STATUSES 콜백(statable/editing.rb:141-153)은 entity 수가 많은 editing에서 위험. entity 일괄 update를 단일 SQL batch 또는 별도 worker로 옮기는 방향 검토 (본 trace에선 발현 안 됨, 예방적 개선).
• APM tracing 세분화: app/models/concerns/statable/editing.rb 의 각 transition 콜백을 custom span(Datadog::Tracing.trace)으로 감싸 다음 발생 시 stall 위치를 즉시 식별할 수 있도록 한다.

단기 개선 (1주 이내)#

• 같은 날 발생한 동종 latency 클러스터 11건을 공통 분모(시각, host, AZ, DB writer 등) 로 묶어 추가 분석 — cluster_ids 의 trace_id들로 APM에서 host/AZ 분포를 확인. 한 host에 집중되어 있다면 host-local 이슈, 분산이면 공유 자원(RDS/ElastiCache) 가설로 좁힌다.
• cupixworks-api Sidekiq client 측 Redis 호출의 p99 latency를 별도 메트릭으로 노출. enqueue가 commit 직전/직후 hop이라 단발성 spike의 흔한 원인.

장기 개선 (재발 방지)#

• Editing 상태 전이의 fan-out 콜백을 표준화된 outbox/dispatcher 패턴으로 옮겨, 요청 처리 시간에서 비동기 후속 작업을 명확히 분리.
• p95/p99 endpoint별 latency budget을 정의하고, 본 클러스터처럼 단발성 outlier가 잡히면 자동으로 trace_id + host 메타데이터를 RCA 입력으로 첨부하는 collector 강화 (현재는 trace_id 1개만 전달).

Monitoring#

• Api::V1::EditingsController#update p95/p99 latency를 timeseries로 추적:

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

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

• 서비스 전체 p95 latency (다른 endpoint의 동시 spike 감지용):

p95:trace.rack.request.duration{service:cupixworks-api} by {resource_name}

• Sidekiq enqueue 지연 (위 H1 가설 검증용, 메트릭 존재 시):

avg:sidekiq.client.push.time{service:cupixworks-api}

• 상태 전이 후속 로그 부재 알람: state transition 로그 발생 후 done/ready/holding 진입 N초 이상 후속 로그 없음 패턴을 monitor로 변환 — 본 RCA는 timeseries widget 대상이 아니므로 monitor 측에서 별도 정의.

Risk Assessment#

• Risk level: low. 단발성 outlier이고 사용자/데이터 영향이 1건의 체감 지연에 국한된다.
• 예상 복잡도: standard — 코드 변경 없이 모니터링 보강만 적용하면 trivial. callback fan-out 분리까지 가면 standard 이상.