RCA: WorkspacesController#trash Latency (10,249ms)

Overview#

What Happened#

2026-06-07 16:11 KST에 Api::V1::WorkspacesController#trash 엔드포인트에서 workspace 4288을 trash 처리할 때 응답 시간이 10,249ms로 측정되었다. 원인은 trash 실행 시 동기적으로 수행되는 다수의 after_trash 콜백이 자식 레코드(facilities, records, captures)를 순회하며 N+1 쿼리를 발생시키기 때문이다.

Quick Facts#

Timeline#

1. 2026-06-07 16:10:54 KST — Workspace 5073 trash 요청 정상 완료 (빠름)
2. 2026-06-07 16:11:22 KST — Workspace 4288 flush_child_cycle_state 콜백 로그 기록
3. 2026-06-07 16:11:32 KST — Workspace 4288 trash 요청 204 응답 완료 (약 10초 소요)
4. 2026-06-07 16:11:32 KST — 에러 스위퍼 latency 클러스터 감지

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::WorkspacesController#trash",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10249,
  "max_ms": 10249,
  "sample_trace_id": "3785510685645700980"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-07 16:11 KST
• 최근 발생: 2026-06-07 16:11 KST

Root Cause Summary#

Workspace를 trash할 때 Cyclable concern의 after_trash 콜백 체인이 HTTP 요청 내에서 동기적으로 실행된다. 구체적으로 stop_children_running_jobs가 workspace의 모든 facilities, records, captures를 .each로 순회하며 각각의 jobs.stoppable을 조회하고, HasManyCaptures 콜백이 never_done captures를 find_each로 순회하며 개별 purge를 호출한다. Workspace 4288이 자식 레코드가 많은 대형 workspace였기 때문에 이 동기적 처리가 10초 이상 소요되었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/cyclable_controller.rb:7
• Repository call: app/repositories/concerns/cyclable_repository.rb:10
• Model trash: app/models/concerns/cyclable.rb:293
• State transition: app/models/concerns/cyclable.rb:56 (trashing event)
• After-transition callback: app/models/concerns/cyclable.rb:149-151
• After-trash callbacks: app/models/concerns/cyclable/jobs_base.rb:8, app/models/concerns/cyclable/callbacks/has_many_captures.rb:11, app/models/concerns/cyclable/workspace.rb:16

1. Controller dispatches to repository:

def trash
  repository.new(model: @model, current_user: current_user).trash
  render_api
end

2. Repository triggers trash! on the model:

def trash
  check_deletable_permission

  @model.cycle_state_updated_by_id = current_user.id if @model.has_attribute?(:cycle_state_updated_by_id)
  @model.trash!
end

3. trash! fires state machine transition + callbacks:

def trash!
  set_cycle_state

  if skip_trash?
    purge!
  else
    run_callbacks :trash do
      if self.class.untrashable?
        trashing_cycle_state!
      else
        deleting_cycle_state!
      end
    end
  end

  delete_cache if respond_to?(:delete_cache)
  flush_cached_permissions if respond_to?(:flush_cached_permissions)
end

Workspace는 untrashable? == true이므로 trashing_cycle_state!가 호출된다.

4. after_transition to: :trashing callback이 즉시 trashed_cycle_state를 호출:

after_transition to: :trashing do |model, transition|
  model.trashed_cycle_state if model.ready_to_trash?
end

5. 핵심 병목 — stop_children_running_jobs (동기적 N+1):

def stop_children_running_jobs
  facilities.each(&:stop_running_jobs)
  records.each(&:stop_running_jobs)
  captures.each(&:stop_running_jobs)

  stop_running_jobs
end

각 호출이 개별적으로 jobs.stoppable 쿼리를 실행:

def stop_running_jobs
  return nil unless respond_to?(:jobs)

  _stoppable_jobs = jobs.stoppable

  return if _stoppable_jobs.blank?

  Cupix::Logger.info("[#{self.class.name}] stop_running_jobs on #{id}: #{_stoppable_jobs.pluck(:id).join(', ')}")

  _stoppable_jobs.each(&:stop!)
end

6. 추가 병목 — HasManyCaptures 콜백 (never_done captures 개별 purge):

after_trash do |model|
  next unless model.respond_to?(:captures)

  never_done_captures = model.captures.never_done

  next unless never_done_captures.exists?

  Cupix::Logger.info("[#{model.class.name}] purge never done capture ids: #{never_done_captures.pluck(:id).join(', ')}")

  never_done_captures.find_each(&:purge)
end

7. 추가 병목 — kick_all_current_users (개별 UPDATE):

def kick_all_current_users
  ::UserRepository.where(current_workspace_id: id).find_each(&:remove_current_workspace!)
end

각 user에 대해 개별 update 호출:

def remove_current_workspace!
  _cache_key = ['user', 'current_workspace', id]
  Rails.cache.delete(_cache_key)

  if current_workspace_id.present? || current_workspace.present?
    self.update(current_workspace: nil, current_workspace_id: nil)
  end
end

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api (4288 OR 5073)
Time range: 2026-06-07T07:05:00Z to 2026-06-07T07:15:00Z

핵심 로그 (KST):

{
  "timestamp": "2026-06-07 16:11:22",
  "status": "info",
  "message": "Requested to flush children with trashed cycle_state for Workspace ID: 4288",
  "class": "Workspace",
  "function": "flush_child_cycle_state"
}

{
  "timestamp": "2026-06-07 16:11:32",
  "status": "info",
  "message": "[204] PUT /api/v1/workspaces/4288/trash (Api::V1::WorkspacesController#trash)"
}

flush_child_cycle_state 로그(16:11:22)와 최종 응답(16:11:32) 사이에 10초 gap이 존재한다. flush_child_cycle_state_in_worker는 FlushCycleStateChildrenWorker.perform_at(10.seconds.from_now, ...) 로 비동기 enqueue하지만, 이 로그 자체는 enqueue 시점에 기록된다. 따라서 이 10초는 flush_child_cycle_state_in_worker 이후에 실행되는 나머지 after_trash 콜백들(stop_children_running_jobs, HasManyCaptures, kick_all_current_users)과 delete_cache, flush_cached_permissions에 소요된 시간이다.

비교: Workspace 5073는 flush_child_cycle_state 로그와 204 응답이 모두 16:10:54에 기록되어 즉시 완료됨. 이는 5073이 자식 레코드가 적은 workspace임을 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/cyclable/jobs/workspace.rb:9-15 — stop_children_running_jobs를 비동기 worker로 이동시킨다. 현재 HTTP 요청 내에서 모든 자식 레코드를 순회하는 것은 workspace 크기에 비례하여 응답 시간이 증가한다.
• app/models/concerns/cyclable/callbacks/has_many_captures.rb:11-21 — never_done_captures.find_each(&:purge) 를 비동기 worker로 분리하거나, batch update로 전환한다.

단기 개선 (1주 이내)#

• kick_all_current_users에서 개별 update 대신 update_all을 사용하여 단일 SQL로 처리한다. cache 삭제도 bulk으로 처리할 수 있다.
• stop_children_running_jobs를 기존 FlushCycleStateChildrenWorker처럼 별도 Sidekiq worker로 분리한다. 이미 perform_at으로 enqueue하는 패턴이 존재하므로 동일한 접근이 가능하다.

장기 개선 (재발 방지)#

• Workspace trash를 이벤트 기반 아키텍처로 전환: 컨트롤러는 cycle_state만 변경하고 응답을 반환, 이후 모든 자식 처리는 worker/event consumer가 비동기적으로 수행한다.
• 대형 workspace에 대한 비동기 trash 패턴 도입 (202 Accepted + polling 또는 webhook).

Monitoring#

• Workspace trash 응답 시간 P95/P99 추적:

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::workspacescontroller_trash} by {workspace_id}

• stop_children_running_jobs 실행 시간에 대한 custom metric 추가
• Threshold alert: WorkspacesController#trash duration > 5000ms

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard — after_trash 콜백을 비동기 worker로 분리하는 것은 기존 FlushCycleStateChildrenWorker 패턴과 동일하며, 데이터 정합성에 영향을 주지 않는 작업들(stop jobs, kick users)이 대상이다.