RCA: Api::V1::JobsController#show Latency (1015ms)

Overview#

What Happened#

2026-05-27 21:24:06 UTC에 us-west-2 리전의 cupixworks-api 서비스에서 Api::V1::JobsController#show 요청이 1015ms 소요되었다. 동일 시간대에 Job 1089729의 상태 전이(preprocessor running → complete)로 인한 대량 DB write가 발생하면서 데이터베이스 부하가 급증했고, 이후 21:29-21:33 UTC에 Elasticsearch 타임아웃으로 전체 API 티어에 걸친 cascading latency가 발생했다.

Quick Facts#

Timeline#

1. 21:24:06Z — JobsController#show 요청 1015ms 소요 (job 1089729, DB 504ms)
2. 21:24:09Z — Job 1089729 running_action 972ms, update 641ms (상태 전이 중)
3. 21:29:26Z — RecordsController#index latency 급증 시작 (2,306ms)
4. 21:30:48Z — Elasticsearch 10초 타임아웃 발생 (502 Bad Gateway)
5. 21:33:20Z — 전체 controller 대상 latency spike (PanosController, BimsController 등)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::JobsController#show",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1015,
  "max_ms": 1015,
  "sample_trace_id": "590007983953586716"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-05-27T21:24:06.309Z
• 최근 발생: 2026-05-27T21:24:06.309Z
• 영향 범위: Job 1089729 조회 요청. 동일 시간대 33%의 JobsController#show 요청이 100ms 이상, 3%가 500ms 이상 소요됨.

Root Cause Summary#

JobsController#show의 1015ms latency는 두 가지 요인의 복합 작용이다: (1) JobRepository.show에서 polymorphic jobable 조회를 위한 추가 DB 쿼리, serialization 단계의 fetch_cache miss로 인한 추가 쿼리, ActionAttribute의 waiting_actions/running_actions eager_load 쿼리 등 총 5-7회의 DB 쿼리가 순차 실행되며, (2) 해당 시점에 Job 1089729의 상태 전이(preprocessor running → complete)로 인한 대량 DB write 부하가 동시에 발생하면서 DB 응답 시간이 급증했다. DB time이 전체 요청의 51% (504ms)를 차지한 것이 이를 확인해준다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/jobs_controller.rb:6 (before_action :set_job)
• set_job → JobRepository.show 호출
• JobRepository.show → Job.find_by_id + polymorphic repository 조회
• show action → render_api → JobSerializer serialization
• JobSerializer → _jobable (fetch_cache), _record (fetch_cache), waiting_actions, running_actions
• Failure point: DB 부하로 인한 전체 쿼리 체인 지연

1. JobRepository.show — 이중 DB 조회

def self.show(id, current_user: nil, **kwargs)
  job = ::Job.find_by_id(id)                    # Query 1: jobs table lookup

  raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: 'Job not found') if job.nil?

  if current_user.present?
    repository_class_name = "#{job.jobable_type}Repository"
    begin
      repository_class = repository_class_name.constantize
    rescue NameError
      raise Cupix::Errors::NotFound.new(code: 'ARG10002', reason: "Repository for #{job.jobable_type} not found")
    end
    repository_class.new(current_user: current_user).show(job.jobable_id, visibility: Cyclable.visibility[:ALL])  # Query 2: polymorphic jobable lookup
  end

  job
end

current_user가 존재하면 Job 조회 후 polymorphic jobable(Capture, Video 등)을 한 번 더 조회한다. 이 결과는 사용되지 않고 access check 목적으로만 실행되나, 해당 repository의 show가 추가 쿼리를 포함할 수 있다.

2. Cachable.fetch_cache — Cache miss 시 추가 쿼리

def fetch_cache(model_name = self.class.name, model_id = self.id)
  return nil if model_id.blank?

  Rails.cache.fetch(cache_key(model_name, model_id), skip_nil: true, expires_in: self.class.cache_expires_in) do
    if self.respond_to?("serialized_#{model_name.underscore}_json".to_sym)
      self.send("serialized_#{model_name.underscore}_json")
    else
      record = model_name.constantize.find_by_id(model_id)  # Cache miss: additional DB query
      record.serialized_json if record.respond_to?(:serialized_json)
    end
  end
end

JobSerializer의 _jobable와 _record attribute가 각각 fetch_cache를 호출한다. Job 1089729가 상태 전이 중이었으므로 after_commit :write_cache가 실행되었을 수 있으나, 타이밍에 따라 cache가 invalidated된 상태에서 miss가 발생하면 DB fallback 쿼리가 실행된다.

3. ActionAttribute — 매 serialization마다 2회 쿼리

def waiting_actions
  actions.waiting.eager_load(:command).map { |action| action.command.name }
end

def running_actions
  actions.running.eager_load(:command).map { |action| action.command.name }
end

module ActionAttribute
  extend ActiveSupport::Concern

  included do
    attribute :waiting_actions
    attribute :running_actions
  end
end

serialization 시 waiting_actions와 running_actions가 각각 actions 테이블을 eager_load(:command)와 함께 쿼리한다. Job 1089729가 상태 전이 중이었으므로 actions 테이블에 대한 write lock과 read 쿼리가 경합했을 가능성이 높다.

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api "JobsController#show" (21:20-21:30 UTC, 2026-05-27)

핵심 latency 데이터 (21:24 UTC 전후):

21:24:07.540Z | JobsController#show | duration: 993.05ms | db_time: 504.33ms (51%) | job_id: 1089729 | host: ip-10-1-80-134
21:24:07.540Z | JobsController#show | duration: 341.96ms | db_time: 187.19ms (55%) | job_id: 1089731 | host: ip-10-1-80-134
21:24:19.558Z | JobsController#show | duration: 260.17ms | db_time: 178.09ms (68%) | job_id: 1089724 | host: ip-10-1-80-134

Job 1089729 상태 전이 로그:

21:24:09.541Z | running_action (preprocessor/running) | duration: 972.97ms | db_time: 166ms
21:24:09.541Z | update | duration: 641.61ms | db_time: 101ms
21:24:47.584Z | update | duration: 551.9ms | db_time: 80ms
21:24:49.586Z | complete_action (preprocessor/complete) | duration: 351.65ms | db_time: 138ms

Elasticsearch 타임아웃 (cascading 원인):

service:cupixworks-api status:error (21:30 UTC)

{
  "class": "RecordRepository",
  "method": "search",
  "message": "Operation timed out after 10002 milliseconds with 0 bytes received",
  "error_code": "BG10002",
  "host": "ip-10-1-19-190",
  "timestamp": "2026-05-27T21:30:48.534Z"
}

21:20-21:30 시간대 JobsController#show 통계:

Total requests: 100
Average duration: 110.4ms
P50: 57.1ms
P95: 373.1ms
Max: 993.0ms
>100ms: 33 (33%)
>500ms: 3 (3%)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 현 시점에서 즉시 조치가 필요한 수준은 아님. 단일 발생(1건)이며 P95 기준 373ms로 일반적 SLO(1초) 이내.

단기 개선 (1주 이내)#

• app/repositories/job_repository.rb:25 — current_user 존재 시 polymorphic repository의 show 호출 결과를 사용하지 않으므로, 권한 체크만 필요하다면 더 가벼운 exists? 또는 accessible_by? 메서드로 대체하여 불필요한 full record 로드를 제거.
• app/models/concerns/actionable.rb:75-81 — waiting_actions와 running_actions를 counter_cache 또는 단일 쿼리로 통합하여 serialization당 2회 쿼리를 1회로 줄이는 것을 검토.

장기 개선 (재발 방지)#

• JobSerializer의 _jobable, _record attribute에 대해 batch preloading 도입: index 액션에서 N+1이 발생하지 않도록 includes/preload 적용.
• Job 상태 전이 시 발생하는 DB write 부하를 분산하기 위해, action 상태 업데이트를 async job으로 분리하거나 batch update로 전환하는 것을 검토.
• fetch_cache miss 시 DB fallback의 latency를 모니터링하는 계측(instrumentation) 추가.

Monitoring#

• JobsController#show P95 latency 알림 (임계값: 500ms)
• DB time 비율 모니터링:

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

• Job 상태 전이 시 concurrent write 수 모니터링:

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

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 단일 발생이며 P95는 정상 범위 내. 다만 Job 상태 전이가 집중되는 시점에 반복 발생 가능성이 있으므로 모니터링 설정 권장.