RCA: ClustersController#create_resource Latency (5057ms)

Overview#

What Happened#

2026-06-03 08:07 KST에 cupixworks-api 서비스의 Api::V1::ClustersController#create_resource 엔드포인트에서 단일 요청이 5057ms의 응답 시간을 기록했다. 해당 엔드포인트의 정상 응답 시간(평균 50-120ms)에 비해 약 42-100배 느린 outlier이다.

Quick Facts#

Timeline#

1. 2026-06-03 08:07 KST — ClustersController#create_resource 요청이 5057ms 소요되어 latency threshold 초과
2. 2026-06-03 08:07 KST — 동일 trace에서 capture postprocessor 완료(JobsController#complete_action), 상태 변경, EditingEntity 생성 등 다수의 DB 작업 동시 발생
3. 2026-06-03 17:07 KST — Error Sweeper에 의해 latency cluster로 수집

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ClustersController#create_resource",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 5057,
  "max_ms": 5057,
  "sample_trace_id": "7160848916220558224"
}

Impact#

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

Root Cause Summary#

ClustersController#create_resource 요청이 set_cluster before_action에서 ClusterRepository.permission_joins를 통해 12개의 LEFT JOIN과 다중 permission 테이블을 결합하는 무거운 SQL 쿼리를 실행한다. 동일 trace(7160848916220558224)에서 capture postprocessor 완료 콜백이 동시에 실행되면서 reset_parent_cached_entity_updates, EditingEntity 생성, capture 상태 변경 등 다수의 DB 쓰기 작업이 발생했다. 이로 인해 DB 커넥션 경합 또는 row-level lock 대기가 발생하여 permission 조회 쿼리가 평소 50-120ms에서 5초 이상으로 지연되었다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/clusters_controller.rb:1 — ClustersController 요청 수신
• Before action: app/controllers/api/v1/clusters_controller.rb:6 — set_cluster가 repository_instance.show(params[:id]) 호출
• Repository show: app/repositories/base_repository.rb:337 — permission_joins(default_joins(current_class), current_user).where(attrs) 실행
• Permission query: app/repositories/cluster_repository.rb:115-298 — 12개 LEFT JOIN으로 permission 체크
• Resource creation: app/controllers/concerns/multiple_resourcable_controller.rb:52-78 — create_resource 실행

before_action :set_cluster, except: %i[index group create untrash purge mock]

def set_cluster
  @model = repository_instance.show(params[:id])
end

query =
  if skip_permission || current_user == ::User.unauthorized_user
    where(attrs)
  elsif current_class == ::Review || (review_id || capture_id).present?
    permission_joins(default_joins(current_class), current_user, review_id: review_id || -1, capture_id: capture_id || -1).where(attrs)
  elsif current_user.present?
    permission_joins(default_joins(current_class), current_user).where(attrs)
  else
    raise Cupix::Errors::System.new(code: 'SYS30000', reason: 'current_user or review is required on Repository')
  end

scope = current_class.visibility_scope(visibility)
model = query.merge(scope).first

ClusterRepository.permission_joins는 12개의 LEFT JOIN 서브쿼리를 생성하여 capture_permissions, record_permissions, facility_permissions, workspace_permissions, team_permissions 테이블에서 사용자의 접근 권한을 확인한다:

def self.default_joins(record)
  record.includes(:storage).joins(:capture, :facility, :workspace).select('
    clusters.*,
    facilities.name AS facility_name,
    facilities.key AS facility_key,
    workspaces.name AS workspace_name,
    captures.name AS capture_name
  ')
end

기대 동작: set_cluster의 permission 쿼리는 인덱스를 활용하여 50-120ms 내에 완료. 실제 동작: 동시에 실행된 postprocessor 콜백의 다수 DB 쓰기로 인해 lock 경합이 발생하여 5057ms 소요.

Log Evidence#

동일 trace ID에서 발생한 동시 작업들:

Datadog query: service:cupixworks-api trace_id:7160848916220558224
Time range: 2026-06-02T22:00:00Z to 2026-06-03T00:30:00Z

{"timestamp": "2026-06-03 08:07:43", "status": "info", "message": "[200] PUT /api/v1/jobs/1100217/actions/postprocessor/complete (Api::V1::JobsController#complete_action)"}
{"timestamp": "2026-06-03 08:07:43", "status": "info", "message": "[Capture] state changed from editing_initial to editing_ready"}
{"timestamp": "2026-06-03 08:07:41", "status": "info", "message": "[Capture] processing_postprocessor_agent_finished"}
{"timestamp": "2026-06-03 08:07:41", "status": "info", "message": "job 1100217 job_stopping_callback done", "class": "JobCallbackWorker"}
{"timestamp": "2026-06-03 08:07:41", "status": "info", "message": "reset Facility (ID: 17133) cached entity updates"}
{"timestamp": "2026-06-03 08:07:39", "status": "info", "message": "[Capture] state changed from finalizing to done"}
{"timestamp": "2026-06-03 08:07:37", "status": "info", "message": "create editing entity on Capture 706786"}
{"timestamp": "2026-06-03 08:07:35", "status": "info", "message": "candidate_editings type: Capture, count: 1", "class": "EditingEntity"}
{"timestamp": "2026-06-03 08:07:33", "status": "info", "message": "create editing on Capture 706786", "class": "EditingEntity"}
{"timestamp": "2026-06-03 08:07:31", "status": "info", "message": "[Capture] state changed from editing_waiting to editing_ready"}

APM 메트릭 분석 (최근 2시간 avg duration):

Metric query: avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::clusterscontroller_create_resource}

정상 시: 50-120ms avg, spike 구간: 300-870ms avg, outlier: 5057ms (단일 요청).

24시간 max duration 메트릭에서도 대부분 50-200ms이나, 특정 시간대에 1.08s, 2.6s까지 spike가 관찰됨. 5057ms는 그 중 최대 outlier.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 조치 불필요. 단일 발생(1회)이며 기능적 오류 없이 성공적으로 응답(200)을 반환했다. DB 부하에 의한 일시적 지연이며 사용자 영향이 미미하다.

단기 개선 (1주 이내)#

• ClusterRepository.permission_joins (cluster_repository.rb:115-298)의 12개 LEFT JOIN 쿼리에 대한 실행 계획(EXPLAIN) 분석. 인덱스 누락 여부 확인.
• set_cluster before_action에서 create_resource 액션이 호출될 때, 이미 check_kind before_action이 실행되므로 permission 체크 순서를 최적화하거나, create_resource에 한하여 경량 permission 체크(owner check 등)를 적용할 수 있는지 검토.

장기 개선 (재발 방지)#

• Permission 체크를 materialized view 또는 캐시 레이어로 분리하여 실시간 12-JOIN 쿼리의 DB 부하를 줄이는 방안 검토.
• Postprocessor 완료 콜백의 DB 쓰기를 비동기(Sidekiq)로 분리하여 API 요청과 동시 실행되는 DB 경합을 최소화.

Monitoring#

• create_resource 엔드포인트에 P95/P99 latency alert 추가:

avg(last_5m):p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::clusterscontroller_create_resource} > 1

• Permission JOIN 쿼리 실행 시간 추적을 위한 커스텀 span 추가 검토.

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (monitoring 추가) / standard (쿼리 최적화)