RCA: Api::V1::JobsController#update Latency

Overview#

What Happened#

2026-05-26 03:2306:16 UTC 사이에 cupixworks-api 서비스의 Api::V1::JobsController#update 엔드포인트에서 평균 1766ms, 최대 3581ms의 응답 지연이 38건 발생했다. 모든 지연 요청은 Job의 state를 stopped로 전환하는 요청이며, state machine의 after_transition 콜백에서 JobCallbackWorker.perform_inline을 통해 동기적으로 실행되는 job_stopped_callback이 1.53.5초간 HTTP 요청을 차단하는 것이 원인이다.

Quick Facts#

Timeline#

1. 2026-05-26T03:23:06Z — 최초 지연 요청 감지 (ap-southeast-2)
2. 2026-05-26T04:34:09Z — 최대 지연 관측 (3998ms, ap-southeast-1)
3. 2026-05-26T06:16:42Z — 마지막 지연 요청 기록
4. 2026-05-26 — RCA 수행

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::JobsController#update",
  "service": "cupixworks-api",
  "occurrences": 38,
  "avg_ms": 1766,
  "max_ms": 3581,
  "sample_trace_id": "3397056429022261873"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 38
• 최초 발생: 2026-05-26T03:23:06.788Z
• 최근 발생: 2026-05-26T06:16:42.343Z
• 영향 범위: 4개 리전(ap-southeast-2, us-west-2, ap-southeast-1, eu-central-1)의 모든 Job state=stopped 업데이트 요청. HTTP 200 응답이므로 기능적 실패는 없으나, 클라이언트 측 타임아웃 또는 UX 저하 가능성 있음.

Root Cause Summary#

Api::V1::JobsController#update에서 Job의 state를 stopped로 전환할 때, state machine의 after_transition 콜백이 JobCallbackWorker.perform_inline(job.id, 'job_stopped_callback')을 호출한다. Sidekiq의 perform_inline은 worker의 perform 메서드를 현재 스레드에서 동기적으로 실행하므로, jobable.job_stopped_callback(job) 전체 로직이 HTTP 요청 라이프사이클 안에서 차단적으로 수행된다. 이 콜백이 1.53.5초 소요되며, 여기에 ParentUpdatable의 cascading update, Cupix::EventService.publish_event의 동기적 Kinesis put_records! 호출, PaperTrail version 생성이 합산되어 총 응답 시간이 1.73.6초에 달한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/jobs_controller.rb:12
• Permission check: app/repositories/job_repository.rb:38 (중복 jobable 조회)
• State transition trigger: app/concerns/parameter/job.rb:54 (@model.stopped_state!)
• Failure point (latency source): app/models/concerns/statable/job.rb:91 (JobCallbackWorker.perform_inline)
• Downstream callback: app/workers/job_callback_worker.rb:10 (job.jobable.send(callback_name, job))
• Cascading update: app/models/concerns/parent_updatable.rb:11
• Kinesis publish: lib/cupix/event_service.rb:43

1. Controller update 진입:

def update
  @model = repository_instance.update(params)

  super
end

2. Repository에서 중복 permission 조회 후 state 전환:

def update(params = {})
  repository_class_name = "#{@model.jobable_type}Repository"
  repository_class = repository_class_name.constantize
  jobable = repository_class.new(current_user: @current_user).show(@model.jobable_id, visibility: Cyclable.visibility[:ALL])
  raise ... if jobable.nil?
  raise ... unless jobable.updatable_by?(@current_user)

  @model.current_user = current_user
  set_parameters(params)  # state machine transition 발생

  @model.save!
  @model
end

set_job before_action에서 이미 수행한 permission 조회를 다시 실행한다 (중복 쿼리).

3. State machine에서 perform_inline 호출 (핵심 병목):

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

perform_inline은 Sidekiq의 동기 실행 메서드로, 현재 HTTP 요청 스레드에서 worker를 즉시 실행한다.

4. Worker가 jobable의 콜백을 동기 실행:

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

  job.jobable.send(callback_name, job)

  Cupix::Logger.info("job #{id} #{callback_name} done", ...)
end

jobable.job_stopped_callback(job)은 polymorphic parent 모델(Capture, Bim, Deviation 등)에 정의된 무거운 콜백으로, DB 조회/갱신, 추가 worker 호출 등을 수행한다.

5. Cascading update로 parent 모델 갱신:

after_update :update_jobable_job_status!

def update_jobable_job_status!
  return if self.jobable.blank?
  return unless self.jobable.update_jobable_when_job_updated? && self.update_jobable_state?

  self.jobable.update({
    error_code: self.error_code,
    processing_status: self.processing_status,
    progress: self.progress,
    running_state: self.state
  })

  if self.has_attribute?(:record_id) && self.record_id.present?
    self.record.update({
      error_code: self.error_code,
      running_state: self.state
    })
  end
end

이 콜백은 jobable과 record 모델을 UPDATE하며, 각 UPDATE가 해당 모델의 after_update 콜백(Eventable, PaperTrail 등)을 연쇄적으로 트리거한다.

6. Kinesis 동기 전송:

def self.publish_event(events = [])
  return if events.blank?
  return if %w[development test].include?(Rails.env)

  records = events.map do |event|
    { data: event.serializable_hash.to_json, partition_key: Current.request_id || SecureRandom.uuid }
  end

  stream_name = "#{::Cupix::Tesla.tenant}-cupixworks-#{Rails.env}-EventStream"
  response = Cupix::Aws::Kinesis.put_records!({ stream_name: stream_name, records: records })
end

Eventable 콜백을 통해 Job, jobable, record 각각의 update마다 동기적으로 Kinesis에 이벤트를 전송한다.

Log Evidence#

Datadog에서 확인된 패턴 — state=stopped 요청만 지연 발생:

service:cupixworks-api resource_name:"Api::V1::JobsController#update" @duration:>500ms env:production

로그 타임라인 (대표 사례):

[07:14:40.312Z] [Job] state changed from running to stopped on Job 194565
[07:14:40.312Z] job 194565, run job_stopped_callback
[07:14:42.314Z] job 194565 job_stopped_callback done         (← ~2000ms 소요)
[07:14:42.314Z] invoke job_stopped_callback with jid: true
[07:14:42.341Z] [200] PUT /api/v1/jobs/194565                (← 총 2647ms)

DB 시간은 전체의 ~10%에 불과:

Duration: 3998ms, DB Time: 227ms (5.7%)  - Job 8602 (ap-southeast-1)
Duration: 3576ms, DB Time: 281ms (7.9%)  - Job 194485 (ap-southeast-2)
Duration: 3325ms, DB Time: 356ms (10.7%) - Job 102847 (eu-central-1)
Duration: 3259ms, DB Time: 688ms (21.1%) - Job 36493 (us-west-2)

state=stopped가 아닌 요청(processing_status 변경만)은 100-300ms 내 완료됨을 확인.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 파일: app/models/concerns/statable/job.rb:91
• JobCallbackWorker.perform_inline을 JobCallbackWorker.perform_async로 변경하여 job_stopped_callback을 비동기 Sidekiq job으로 실행하도록 수정. perform_inline은 HTTP 요청 내에서 동기 실행되므로, 이를 비동기로 전환하면 응답 시간이 즉시 100-300ms 수준으로 감소할 것으로 예상.
• 동일하게 :stopping transition의 perform_inline (line 96)도 perform_async로 변경 권장.

단기 개선 (1주 이내)#

• JobRepository#update (line 38)에서 수행하는 중복 jobable 조회 제거. set_job before_action에서 이미 permission check을 수행하므로, repository에서 다시 조회할 필요 없음.
• Cupix::EventService.publish_event를 비동기로 전환 (ActiveJob 또는 Sidekiq worker 통해 Kinesis 전송). 현재 Job/jobable/record 각각의 update마다 동기 Kinesis 호출이 발생.

장기 개선 (재발 방지)#

• 모든 state machine after_transition 콜백에서 perform_inline 사용을 perform_async로 일괄 전환하는 정책 수립 (:pending, :running transition 포함 — line 78, 82).
• ParentUpdatable의 cascading update에서 발생하는 Eventable 콜백 연쇄를 정리: Job update 시 불필요한 event 중복 생성 방지.
• State transition 전용 비동기 파이프라인 도입 — HTTP 응답은 state 변경만 즉시 반환하고, 후속 처리(callback, event, cascading update)는 별도 worker에서 처리.

Monitoring#

• state=stopped 요청의 P95/P99 응답 시간 모니터링:

service:cupixworks-api resource_name:"Api::V1::JobsController#update" @http.status_code:200 @duration:>1000ms

• job_stopped_callback 실행 시간 별도 추적:

service:cupixworks-api "job_stopped_callback done" | pattern

• Kinesis put_records 지연 모니터링:

service:cupixworks-api "Published event" @duration:>200ms

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — perform_inline → perform_async 변경은 간단하나, 비동기 전환 시 callback 실행 순서 보장 여부 및 경쟁 조건 검토 필요. job_stopped_callback 내부에서 jobable 상태에 의존하는 로직이 있다면 타이밍 이슈 가능.