RCA: Api::V1::JobsController#update latency (avg 11319ms)

Overview#

What Happened#

2026-06-24 20:50 KST 경 cupixworks-api ap-southeast-2 리전에서 PUT /api/v1/jobs/:id (Api::V1::JobsController#update) 요청 1건이 11.3초 동안 처리되어 latency 임계치를 초과했다. 요청은 cupix-agent가 state=stopped로 작업 상태를 갱신한 호출이었고, 응답은 200 정상이었다. 11초 중 DB 시간은 267ms (~2.4%) 뿐이며 나머지는 state machine 전이로 인해 동기적으로 실행된 Ruby 콜백 체인이 차지했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-24 20:50:51 KST — 클라이언트(cupix-agent)가 PUT /api/v1/jobs/211454로 state=stopped 전송. 상태 전이 running → stopped 로그 기록.
2. 2026-06-24 20:50:51 KST — JobCallbackWorker.perform_inline(211454, 'job_stopped_callback') 시작 (after_transition any => :stopped 훅에서 동기 실행).
3. 2026-06-24 20:50:55 KST — job_stopped_callback done 로그 기록 (콜백 자체 약 4초 소요).
4. 2026-06-24 20:51:04.698 KST — HTTP 200 응답 반환. 총 duration=11318.14ms, db=267.38ms.
5. 2026-06-24 추후 — error-sweeper가 동일 cluster_type=latency 11건을 svc:cupixworks-api::unknown 인시던트로 묶음 (status-board: 2026-06-24-svc-cupixworks-api--unknown-1).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::JobsController#update",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11319,
  "max_ms": 11319,
  "sample_trace_id": "3588110070409622913"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (resource_name 기준 단일 trace, 클러스터는 latency 임계치 초과 1건만 잡음)
• 최초 발생: 2026-06-24 20:50:51 KST
• 최근 발생: 2026-06-24 20:50:51 KST
• 직접적 사용자 영향은 1건이지만, cupix-agent 측에서는 stopped 상태 보고가 11초 동안 블로킹되어 처리 파이프라인의 후속 단계(SQS visibility, 다음 작업 폴링) 지연 가능. 동시에 동일 인스턴스(ip-10-1-81-208)의 Puma worker가 11초 점유되어 동시 처리량 감소.

Root Cause Summary#

Api::V1::JobsController#update는 JobRepository#update → Parameter::Job#set_parameters 경로에서 state=stopped를 받아 @model.stopped_state!를 호출한다. Statable::Job의 state machine after_transition any => :stopped 훅은 JobCallbackWorker.perform_inline(job.id, 'job_stopped_callback')로 콜백을 요청 스레드에서 동기 실행(perform_inline) 한다. 해당 콜백(Jobable::Capture#job_stopped_callback)은 update_refinement_state, initiate_editing_state, start_finalization(Editing 엔터티 생성/상태 전이), processing_finished_at 업데이트, log_trace_event('processing_finished'), done_state, check_refinement_on_job_stopped, check_reconstruction_state_on_job_stopped 등 다수의 무거운 DB 갱신·상태 전이·이벤트 로깅을 수행한다. DB 누적 시간은 267ms로 작지만 Ruby 측 로직과 콜백 체인이 11초를 소모해, agent 동기 API 호출이 P99 SLA를 초과했다. 별도 예외/에러 없이 200으로 종료되었으므로 outage가 아닌 설계상의 동기 콜백 경로 지연이 근본 원인이다.

Technical Analysis#

Code Path#

• Entry: app/controllers/api/v1/jobs_controller.rb:12-16 — JobRepository#update(params) 호출 후 super로 응답 직렬화.

def update
  @model = repository_instance.update(params)

  super
end

• Repository: app/repositories/job_repository.rb:31-53 — set_parameters(params)로 모델에 변경 사항을 적용한 뒤 @model.save!.

@model.current_user = current_user

set_parameters(params)

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

• Parameter mapping: app/concerns/parameter/job.rb:33-62 — params[:state] == 'stopped'이면 @model.stopped_state! 이벤트를 트리거 (state machine 이벤트 메서드는 동기적으로 모든 콜백을 실행).

when 'stopped'
  raise Cupix::Errors::InvalidState.new(code: 'STAT40000', reason: 'State not changed') if @model.stopped?

  @model.stopped_state!

• State machine hook: app/models/concerns/statable/job.rb:86-93 — any => :stopped 전이 후 PullTaskWorker.perform_in(20s, …)와 JobCallbackWorker.perform_inline(...)을 호출. perform_inline은 Sidekiq 큐에 enqueue하지 않고 현재 스레드에서 동기 실행한다.

after_transition any => :stopped do |job, transition|
  job.aws_tasks.each do |task|
    PullTaskWorker.perform_in(20.second, task.id)
  end

  jid = JobCallbackWorker.perform_inline(job.id, 'job_stopped_callback')
  Cupix::Logger.info("invoke job_stopped_callback with jid: #{jid} for job #{job.id}")
end

• Inline callback executor: app/workers/job_callback_worker.rb:5-15 — job.jobable.send(callback_name, job) 호출. 본 사건에서는 Capture#job_stopped_callback.

def perform(id, callback_name)
  Cupix::Logger.info("job #{id}, run #{callback_name}", class: self.class.name, function: __method__, job: { id: id, callback: callback_name })
  job = ::Job.find_by_id(id)
  return if job.nil?

  job.jobable.send(callback_name, job)

• Failure (latency) point: app/models/concerns/jobable/capture.rb:29-48 — 다수의 DB 갱신·상태 전이·이벤트 로깅이 한 요청 라이프사이클 안에서 직렬로 실행됨.

def job_stopped_callback(job)
  run_callbacks(:job_stopped_callback) do
    if job.update_jobable_state?
      # TODO: TSLA-4544 initiate_editing_state will be removed when SQA released
      update_refinement_state
      initiate_editing_state
      start_finalization
      update(processing_finished_at: DateTime.now)
      stat_processing_finished_at if self.respond_to?(:stat_processing_finished_at)
      self.log_trace_event('processing_finished')
      self.error_code = job.error_code if job.error_code.present?
      flush_record_geo_coordinate_in_worker if record_geo_coordinate_flush_required?

      done_state
    end

    check_refinement_on_job_stopped(job)
    check_reconstruction_state_on_job_stopped(job)
  end
end

기대 동작: 클라이언트의 상태 보고 API는 짧게(<500ms) 끝나고 후속 finalize/editing 전이는 Sidekiq 큐로 분리되어야 함. 실제 동작: perform_inline으로 전체 callback chain을 요청 스레드에서 실행 → 11.3초 응답.

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api "JobsController#update" @duration:>5000
service:cupixworks-api "PUT /api/v1/jobs/211454"
service:cupixworks-api "job 211454"

느린 요청 본문 (Datadog raw):

{
  "duration": 11318.14,
  "db": 267.38,
  "controller": "Api::V1::JobsController",
  "action": "update",
  "params": {
    "state": "stopped",
    "id": "211454"
  },
  "user_agent": "cupix-agent",
  "team": { "domain": "built", "id": 16 },
  "http": {
    "url_details": { "path": "/api/v1/jobs/211454" },
    "status_code": 200,
    "method": "PUT"
  },
  "host": { "name": "ip-10-1-81-208.ap-southeast-2.compute.internal" },
  "@timestamp": "2026-06-24T11:51:04.698Z",
  "tags": ["region:ap-southeast-2", "version:production-ap-southeast-2-20260624t0820z0-24b9962e-cupixworks"]
}

콜백 진행 흐름 (KST):

2026-06-24 20:50:51  [Job] state changed from running to stopped on Job 211454
2026-06-24 20:50:51  job 211454, run job_stopped_callback        (JobCallbackWorker#perform)
2026-06-24 20:50:55  job 211454 job_stopped_callback done        (JobCallbackWorker#perform)
2026-06-24 20:50:55  invoke job_stopped_callback with jid: true for job 211454
2026-06-24 20:51:04  [200] PUT /api/v1/jobs/211454 (Api::V1::JobsController#update)  duration=11318ms db=267ms

핵심 신호:

• 콜백 자체 4초 (20:50:51 → 20:50:55)
• 응답까지 추가 9초 (20:50:55 → 20:51:04) — 콜백 종료 후 super의 직렬화(view: 0.06이므로 view는 아님)와 save! 후 트랜잭션 commit, paper_trail, ParentUpdatable 등에서 더 시간이 소모됨. 추가 trace 단위 breakdown은 APM Flamegraph에서 확인 필요 — uncertain.
• DB 누적 시간은 267ms로 매우 짧음 → DB lock contention/외부 의존성 outage가 아니라 Ruby 측 동기 콜백 체인이 지배적.
• 동일 시간대 다른 JobsController#update 호출(같은 host, 같은 region) 다수는 정상 응답 (예: job 211431, duration 356.98ms, processing_status: 3d-reconstruction만 부분 갱신, state 없음). state 전이가 없는 update는 빠르고, state=stopped 케이스만 비대.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 핫픽스 차원의 코드 변경은 권장하지 않음. 단발성 11초 1건이며 데이터 손상은 없음. 상황 모니터링과 P95/P99 추적이 우선.
• 단, 동일 패턴이 svc:cupixworks-api::unknown 인시던트(2026-06-24-svc-cupixworks-api--unknown-1)의 다른 cluster에서도 누적된다면 임시로 ap-southeast-2 인스턴스에 한해 Puma worker_timeout을 15초 이상으로 두어 Sidekiq inline 도중 timeout으로 종료되지 않게 한다.

단기 개선 (1주 이내)#

• app/models/concerns/statable/job.rb:91 의 JobCallbackWorker.perform_inline 을 비동기(perform_async) 로 전환하는 것을 검토. agent → API 응답 시간을 분리하고, finalize/editing 전이는 Sidekiq에서 수행한다. 단, 다음 호출자가 callback의 즉시 일관성을 기대하는지(processing_finished_at, done_state 등) 확인 후 변경해야 한다.
• 또는 Jobable::Capture#job_stopped_callback 내부에서 가장 무거운 단계(start_finalization → editing 엔티티 생성/전이, log_trace_event)만 별도 Sidekiq 작업으로 분리.
• Api::V1::JobsController#update에 APM custom span을 추가하여 callback chain의 step별 시간(update_refinement_state, start_finalization, done_state)을 분해 측정.

장기 개선 (재발 방지)#

• agent ↔ API 상태 보고는 얇은 acknowledge 패턴으로 재설계: API는 상태 전이를 enqueue만 하고 200을 즉시 반환, 실제 후속 처리는 Sidekiq 큐에서 수행. 현재 JobCallbackWorker는 이미 비동기 워커이지만 perform_inline으로 동기 호출되고 있어 설계 의도와 어긋난다.
• state machine after_transition 훅에서 외부 가시 IO 또는 다단계 상태 전이를 동기 실행하는 패턴 전체에 대한 audit (grep -r perform_inline app/models).
• JobsController#update 에 P95 응답 시간 SLO(예: 1s)와 SLO violation 시 PagerDuty 알람 정의.

Monitoring#

• Api::V1::JobsController#update resource_name 의 latency p95/p99 추세 그래프 (Datadog APM):

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::jobscontroller#update,env:production} by {region}

• state=stopped 케이스에 한정한 동기 콜백 체인의 frequency:

service:cupixworks-api "invoke job_stopped_callback with jid"

• duration > 5000ms 인 update 요청 비율:

service:cupixworks-api "JobsController#update" @duration:>5000

• JobCallbackWorker inline 실행 시간 추적 — job_stopped_callback done 로그와 직전 run job_stopped_callback 로그 사이 간격을 metric으로 추출 (Datadog log-based metric 생성 권장).

Risk Assessment#

• Risk level: low (현재 1회 발생, 데이터 손상 없음, 응답은 200 정상)
• 영향 확대 가능성: medium — 동일 패턴이 누적되면 agent 측 SQS visibility timeout 만료로 인한 작업 중복 실행 위험. ap-southeast-2 트래픽 증가 시 더 빈번해질 수 있음.
• 예상 복잡도: standard — perform_inline → perform_async 전환은 트리비얼하지만 callback 즉시 일관성 의존 호출자 확인이 필요. 회귀 테스트 범위 mid.