RCA: Api::V1::Admin::EditingsController#add_reviewer latency (avg 12878ms)

Overview#

What Happened#

2026-07-03 18:02 KST 경 cupixworks-api production(us-west-2)의 PUT /api/v1/admin/editings/:id/add_reviewer 요청 한 건이 12,838ms 만에 완료됐다. 같은 세션에서 Retool 어드민 사용자가 다수의 add_reviewer 호출을 연달아 던지고 있었고, 그중 하나가 12초대 tail latency를 기록하면서 latency 클러스터가 생성됐다. Datadog trace metric의 request duration 만 감지된 이벤트로, exception 은 발생하지 않았다.

Quick Facts#

Affected Teams#

status-board 는 같은 시간대 cupixworks-api 서비스 저하 인시던트(2026-07-03-svc-cupixworks-api--unknown-1, 08:08 KST~open) 에 이 클러스터를 묶어두었으나, root_cause_type 이 unknown 이므로 참고용이다.

Timeline#

1. 2026-07-03 18:02:32 KST — Retool 세션에서 PUT /api/v1/admin/editings/1203847/add_reviewer 요청 시작 (request_id: 74f60711-09c2-4fe6-a499-6ee6afaab279).
2. 2026-07-03 18:02:33 KST — EditingPriorityScorer#calculate 완료 로그(Priority score calculated) 기록 — 스코어링 자체는 ~1초 내에 끝남.
3. 2026-07-03 18:02:45.572 KST — 동일 요청이 [200] 응답으로 종료, duration: 12838.61ms, db: 787.15ms.
4. 2026-07-03 18:02 KST 전후 — 같은 세션에서 유사 요청이 다수 발생 (1203834 1751ms, 1203902 5188ms 등) — 배치 리뷰어 배정 워크로드.
5. 2026-07-03 09:02:32 UTC — error-sweeper 가 latency 클러스터 3caa3b99-… 생성.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::Admin::EditingsController#add_reviewer",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 12878,
  "max_ms": 12878,
  "sample_trace_id": "6121055689335544324"
}

Datadog 요청 로그에서 관측된 실제 응답:

{
  "@timestamp": "2026-07-03T09:02:45.572Z",
  "message": "[200] PUT /api/v1/admin/editings/1203847/add_reviewer",
  "controller": "Api::V1::Admin::EditingsController",
  "action": "add_reviewer",
  "duration": 12838.61,
  "db": 787.15,
  "serialization": { "duration": 0 },
  "user_agent": "Retool/2.0 (+https://docs.tryretool.com/docs/apis)",
  "user": { "id": 14807, "email": "bella.lee@cupix.com", "team": { "id": 133 } },
  "http": { "status_code": 200, "method": "PUT" },
  "request_id": "74f60711-09c2-4fe6-a499-6ee6afaab279",
  "version": "production-us-west-2-20260703t0842z0-13e7c827-cupixworks"
}

serialization.duration 이 0 이고 db 가 787ms 에 불과한데도 총 duration 이 12.8s 로 벌어졌다. 즉 12s 가량은 Rails DB/serializer 밖 — Elasticsearch HTTP 호출 및 GC/GVL 대기 등 외부 I/O 에서 소진됐다.

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (cluster_type: latency, 임계값 이상 span 이 1건만 잡힘)
• 최초 발생: 2026-07-03 18:02 KST
• 최근 발생: 2026-07-03 18:02 KST
• 사용자 체감 영향: Retool 어드민 리뷰어 배정 UI 응답 12초 지연 1건. 같은 세션의 다른 add_reviewer 요청도 1.7–5.2s 로 chronically 느림 — 배치 배정 UX 저하가 상시적이다.

Root Cause Summary#

Api::V1::Admin::EditingsController#add_reviewer 는 요청 컨텍스트 안에서 두 개의 Elasticsearch 라운드트립을 동기적으로 수행한다. (1) Reviewer.create! 의 after_commit :reindex_reviewable 콜백이 부모 Editing 문서 전체를 _index_document 로 재색인(elasticsearch client.index 호출), (2) 이어서 EditingPriorityScorer.call 이 @editing.update!(priority_score:) 을 실행해 Editing._update_document 로 다시 ES client.update 를 호출. db: 787ms 뿐인데 duration: 12838ms 인 것은 이 두 ES 호출 및 as_indexed_json 직렬화가 요청 스레드를 점유했기 때문이다. 이번 event 는 그중 하나가 ES tail latency (또는 tmp_index 로의 dual write, Searchable._index_document 에서 fetch_tmp_index_name 조건부 두 번째 index 호출) 를 만나 12초까지 늘어난 케이스다.

Technical Analysis#

Code Path#

Entry point — controller action:

def add_reviewer
  repository_instance.add_reviewer(params)
  render_api Renderable.new({
    contents: @model,
    serializer_option: @serializer_option
  })
end

Repository 에서 두 개의 무거운 작업을 순차 실행:

def add_reviewer(params)
  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'user_id is required') if params[:user_id].nil?

  user = User.find_by(team: current_user.team, id: params[:user_id])

  raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Reviewer not found') if user.blank?

  existing_reviewer = self.model.reviewers.find_by(user: user)
  return existing_reviewer if existing_reviewer

  self.model.reviewers.create!(user: user).tap do
    EditingPriorityScorer.new(editing_id: self.model.id, editor_id: user.id).call
  end
end

reviewers.create! 성공 시 Reviewer 모델의 after_commit 콜백이 발동:

class Reviewer < ApplicationRecord
  include ::Statable::Reviewer
  include ::Cachable::Reviewer
  include ::DataWareHouse::Reviewer
  belongs_to :reviewable, polymorphic: true
  belongs_to :user

  after_commit :reindex_reviewable, on: %i[create destroy]

  def reindex_reviewable
    target = reviewable
    return if target.blank? || target.destroyed?

    target._index_document
  end
end

_index_document 는 요청 스레드에서 직접 ES 로 client.index 를 부르고, fetch_tmp_index_name 이 non-nil 이면 tmp index 로 한 번 더 호출한다 — 요청 지연의 첫 번째 원인:

def _index_document
  return if @skip_index_document == true

  indexed_json = __elasticsearch__.as_indexed_json
  base_request = {
    id: __elasticsearch__.id,
    body: indexed_json
  }

  results = __elasticsearch__.client.index(base_request.merge(index: __elasticsearch__.index_name))
  Cupix::Logger.debug(results.to_json, class: self.class.name, function: __method__)

  # NOTE: dual write to tmp_index while reindexing
  if (tmp_index = self.class.fetch_tmp_index_name)
    __elasticsearch__.client.index(base_request.merge(index: tmp_index))
  end
rescue StandardError => e
  Cupix::Logger.error("Index error - #{e.message}", class: self.class.name, function: __method__)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

as_indexed_json 은 EditingSerializer 전체를 실행 — user, editor, team, workspace, facility, level, record, workarea, stat, reviewers 등 다수 어소시에이션을 렌더링한다 (app/models/concerns/searchable/editing.rb:169-216, app/serializers/editing_serializer.rb:1-69).

두 번째 무거운 지점 — EditingPriorityScorer#call 이 다시 editing 을 update:

def initialize(editing_id:, editor_id: nil)
  @editing = ::Editing.find(editing_id)
  @editor = editor_id ? ::User.find(editor_id) : nil
end

def call
  return nil unless @editing.editing_type == 'normal'

  score = calculate
  return nil if score.nil?

  @editing.update!(priority_score: score)
  score
end

Editing#update!(priority_score:) 는 Searchable 의 after_commit on: [:update] 훅에 의해 다시 ES 로 _update_document (client.update + optional tmp_index dual write) 를 호출한다:

after_commit on: [:create] do
  _index_document
end

after_commit on: [:update] do
  _update_document
end

after_commit on: [:destroy] do
  _delete_document
end

Failure point (성능 관점): reviewable_repository.rb:14 의 reviewers.create! 및 EditingPriorityScorer#call 안의 update! 두 지점 — 각각 동기 ES 라운드트립을 유발.

기대 동작: 리뷰어 추가/우선순위 재계산 후 색인 갱신은 백그라운드로 처리되어 요청 응답은 500ms 이하. 실제 동작: 두 개의 ES 라운드트립 + full serializer 재실행이 요청 스레드에서 순차 수행되며 tail case 에서 12s 이상 소요.

Log Evidence#

Datadog 쿼리 (요청 로그):

service:cupixworks-api "admin/editings" "add_reviewer"
from: 2026-07-03T09:02:00Z
to:   2026-07-03T09:03:00Z

핵심 응답 로그 (slow one) — duration 대비 db 가 극히 작음:

{
  "@timestamp": "2026-07-03T09:02:45.572Z",
  "params": { "id": "1203847" },
  "duration": 12838.61,
  "db": 787.15,
  "serialization": { "duration": 0 },
  "http": { "status_code": 200, "method": "PUT" },
  "user_agent": "Retool/2.0"
}

같은 세션의 다른 요청도 이미 상당히 느림 — 상시적인 slow-path 임을 뒷받침:

[
  { "path": "/api/v1/admin/editings/1203834/add_reviewer", "duration": 1751.19, "db": 867.18, "@timestamp": "2026-07-03T09:02:18.950Z" },
  { "path": "/api/v1/admin/editings/1203902/add_reviewer", "duration": 5187.99, "db": null,   "@timestamp": "2026-07-03T09:02:xx" }
]

EditingPriorityScorer 실행 자체는 짧다 — Datadog 에 Priority score calculated 로그가 요청 시작 ~1초 후에 남음:

Datadog query: service:cupixworks-api "Priority score calculated"
from: 2026-07-03T09:00:00Z, to: 2026-07-03T09:05:00Z

[
  { "@timestamp": "2026-07-03T09:02:33.xxxZ", "message": "Priority score calculated", "class": "EditingPriorityScorer", "function": "calculate" },
  { "@timestamp": "2026-07-03T09:04:57.xxxZ", "message": "Priority score calculated", "class": "EditingPriorityScorer", "function": "calculate" }
]

즉 scoring 로직 자체는 ~1s, 나머지 ~11s 는 scoring 이후의 update! → _update_document 호출과 처음의 create! → _index_document 호출에서 발생한 것으로 해석된다. Serializer duration 이 0 인 이유는 마지막 응답 렌더 단계의 서라이저 시간만 기록되기 때문이며, ES 재색인용 as_indexed_json 은 controller 계측 대상이 아니다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. 단일 12s outlier 이며 exception 아님. immediate 롤백/hotfix 대상은 아니다.
• 다만 관측 강화: Reviewer.reindex_reviewable 과 Editing._index_document / _update_document 에 duration 계측 추가 (Datadog custom metric or span tag). app/models/reviewer.rb:10-15, app/models/concerns/searchable.rb:34-53, app/models/concerns/searchable.rb:55-121.

단기 개선 (1주 이내)#

• 동기 재색인 → 비동기 워커화: Reviewer.after_commit :reindex_reviewable 이 요청 컨텍스트에서 _index_document 를 실행하는 대신 BulkIndexWorker.perform_async('Editing', [reviewable.id], 'index') 로 밀어넣도록 변경. app/models/reviewer.rb:8-15.
• Priority scoring 도 async 후보: reviewable_repository.rb:14 의 .tap { EditingPriorityScorer.new(...).call } 를 워커화 (EditingPriorityScorer 를 감싸는 Sidekiq job). scoring 후 update! 가 유발하는 두 번째 ES 호출을 요청 밖으로 뺀다.
• existing_reviewer short-circuit 이후에도 실제 create 만 재색인: 현재는 정상 경로에서만 create → reindex 이므로 별도 조치는 불필요. 다만 EditingPriorityScorer 는 existing_reviewer 리턴 케이스에서도 호출되지 않는지 확인 필요 (reviewable_repository.rb:12-16, 현재 코드상 return existing_reviewer 로 스코어링 skip 되므로 OK).

장기 개선 (재발 방지)#

• Searchable concern 이 default 로 동기 색인하는 정책을 재검토. 대량 어드민 조작(리뷰어 배정, 상태 변경) 유즈케이스에 대해 opt-in 비동기 색인 채널을 표준화.
• Retool 등 배치성 클라이언트가 add_reviewer 를 다건 순차 호출하는 패턴 → bulk 엔드포인트 (POST /api/v1/admin/editings/bulk_add_reviewer) 신설 검토. 한 번의 트랜잭션 + 한 번의 ES bulk index 로 축약.
• APM 에서 resource_name:Api::V1::Admin::EditingsController#add_reviewer p95/p99 SLO 정의 및 회귀 감시.

Monitoring#

Datadog dashboard timeseries widget 용 쿼리 (모두 writing-datadog-monitoring-queries 가이드에 따라 metric 형태로 작성):

add_reviewer p95 latency:

p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::admin::editingscontroller#add_reviewer,env:production}

add_reviewer p99 latency:

p99:trace.rack.request{service:cupixworks-api,resource_name:api::v1::admin::editingscontroller#add_reviewer,env:production}

add_reviewer 요청량:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::admin::editingscontroller#add_reviewer,env:production}.as_rate()

Elasticsearch 클라이언트 outbound latency (Editing 관련 지연 파악용):

avg:trace.rest_client.request{service:cupixworks-api,env:production}

BulkIndexWorker 호출량 (비동기 색인 워커로 이관 시 검증용):

sum:sidekiq.jobs.processed{service:cupixworks-worker,queue:default,job:bulkindexworker}.as_rate()

Risk Assessment#

• Risk level: low — 사용자 대면 exception 없음, 단일 outlier. 다만 admin UX 지연이 반복되면 medium 으로 상향 가능.
• 예상 복잡도: standard — Reviewer.reindex_reviewable 및 EditingPriorityScorer 를 비동기화하는 변경은 회귀 리스크(색인 지연으로 인한 검색 결과 stale)가 있어 QA/스테이징 확인 필요. BulkIndexWorker 는 이미 존재하므로 신규 인프라는 불필요.