RCA: PanosController#check_uploading Latency (avg 647ms, max 889ms)

Overview#

What Happened#

2026-05-12 05:12~05:19 UTC 사이에 cupixworks-api 서비스의 Api::V1::PanosController#check_uploading 엔드포인트에서 평균 647ms, 최대 889ms의 응답 지연이 발생했다. ap-southeast-2와 us-west-2 리전에서 총 55건의 느린 요청이 감지되었다. 모든 요청은 HTTP 200으로 정상 응답하였으나, 500ms 이상의 지연이 지속적으로 관찰되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 05:12:07Z — 첫 번째 느린 check_uploading 요청 감지
2. 05:19:44Z — 마지막 느린 요청 감지 (약 7.5분간 지속)
3. 05:19:54Z — 같은 시간대 PanosController#bulk 요청 6.9초 소요 (DB 1.3초), ap-southeast-2 호스트에서 심한 부하 발생
4. 2026-05-12 — RCA 분석 수행

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#check_uploading",
  "service": "cupixworks-api",
  "occurrences": 55,
  "avg_ms": 647,
  "max_ms": 889,
  "sample_trace_id": "6913185045848510153"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 55
• 최초 발생: 2026-05-12T05:12:07.973Z
• 최근 발생: 2026-05-12T05:19:44.459Z

Root Cause Summary#

check_uploading 엔드포인트의 지연은 두 가지 요인의 복합 결과이다. 첫째, before_action :set_pano에서 실행하는 PanoRepository.default_joins 쿼리가 captures, levels, records, facilities, workspaces, teams, clusters, masks, capture_types, cameras 등 10개 이상의 테이블을 JOIN하고 40개 이상의 컬럼을 SELECT하는 무거운 쿼리이다. check_uploading 액션은 pano의 upload 상태만 확인하면 되므로 이 복잡한 JOIN은 불필요하다. 둘째, Resource#check_uploading에서 _object.exists?를 호출할 때 AWS S3에 대한 동기 HEAD 요청이 발생하며, 이 네트워크 I/O가 요청당 수백ms의 오버헤드를 추가한다. Datadog 로그에서 DB 시간은 평균 60-100ms에 불과하나 전체 응답 시간은 600-900ms로, 나머지 500-800ms가 S3 HEAD 요청과 Rails 미들웨어 처리에서 소비된다. 동시간대에 PanosController#bulk 요청이 최대 6.9초(DB 1.3초) 소요되어 DB 커넥션 풀 경합도 발생했다.

Technical Analysis#

Code Path#

1. Entry point: app/controllers/api/v1/panos_controller.rb:77 — check_uploading 액션 호출

def check_uploading
  pano = repository_instance.check_uploading

  render_api Renderable.new({
    contents: @model,
    serializer_option: @serializer_option
  })
end

2. before_action :set_pano (app/controllers/api/v1/panos_controller.rb:8,115-117): check_uploading은 except 목록에 없으므로 set_pano가 실행된다. 이 필터는 PanoRepository#show를 호출하며, 내부적으로 default_joins를 통해 10개 이상의 JOIN이 포함된 무거운 쿼리를 실행한다.

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

def self.default_joins(record)
  record.joins(:capture, { capture: :level }, :record, :facility, :workspace, :team).joins("
    LEFT JOIN clusters ON clusters.id = panos.cluster_id
    LEFT JOIN masks ON masks.id = panos.mask_id AND masks.maskable_type = 'Pano'
    LEFT JOIN capture_types ON capture_types.id = captures.capture_type_id
    LEFT JOIN cameras ON cameras.id = captures.camera_id
  ").select('
    panos.*,
    clusters.name AS cluster_name,
    clusters.ancestry AS cluster_ancestry,
    captures.name AS capture_name,
    ...40+ columns...
  ')
end

3. Repository check_uploading (app/repositories/pano_repository.rb:421-425): @model.check_resource_uploading! 호출

def check_uploading
  @model.check_resource_uploading!
  @model
end

4. Pano model (app/models/concerns/resourcable/pano.rb:24-33): resource_state가 created, uploading, missing 중 하나면 resource의 upload 상태를 확인한다. resource 호출 시 resources.where(kind: nil).first 쿼리 추가 실행.

def check_resource_uploading!
  if %I[created uploading missing].include?(resource_state_name)
    if resource.check_uploading
      self.uploaded_resource_state
    else
      self.missing_resource_state
      raise Cupix::Errors::Resource.new(code: 'RESC10000', reason: 'Resource does not uploaded')
    end
  end
end

5. Failure point (latency source): app/models/concerns/storagable/resource.rb:163-183 — _object.exists?가 S3 HEAD 요청을 수행하며, 이것이 주요 지연 원인이다.

def check_uploading
  _revision = self.revision
  _object = self.object(_revision + 1)

  if _object.exists?          # ← S3 HEAD request (blocking I/O)
    self.etag = _object.etag.gsub('"', '') rescue nil
    self.size = _object.size
    self.content_type = _object.content_type rescue nil

    return false if self.size.blank? || self.size.zero?

    MidasOperation.record_attachment_upload(attachment: resourcable, file_size: self.size) if resourcable.is_a?(Attachment)

    self.increase_revision
    self.done
    true
  else
    self.missing
    false
  end
end

6. S3 Object 생성 (app/models/concerns/storagable/resource.rb:85-99): Cupix::StorageService.object를 통해 Aws::S3::Object 인스턴스를 생성한다. 이후 .exists? 호출 시 실제 S3 HEAD 요청이 발생.

def object(storage_option: nil, **kwargs)
  opts = parse_storage_option(storage_option).merge(kwargs)
  opts[:force_path_style] = true

  check_required_params(opts, %i[region bucket_name key])

  Aws::S3::Object.new(opts)
end

기대 동작: check_uploading은 빠른 상태 확인 후 즉시 응답해야 한다. 실제 동작: (1) 10+ JOIN 쿼리로 DB 60-150ms 소요, (2) S3 HEAD 요청으로 추가 400-700ms 소요, 총 600-900ms.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "check_uploading" @duration:>500ms
Time: 2026-05-12T04:12:00Z ~ 2026-05-12T05:30:00Z

핵심 로그 항목 (ap-southeast-2, hawkins 팀):

{
  "timestamp": "2026-05-12T05:19:28.397Z",
  "pano_id": 12955858,
  "duration_ms": 886.55,
  "db_time_ms": 62.67,
  "overhead_ms": 823.88,
  "host": "ip-10-1-146-78.ap-southeast-2.compute.internal",
  "user": "mario.basile1@hawkins.co.nz",
  "team": "hawkins",
  "user_agent": "cupix-agent",
  "auth": "COGNITO",
  "status": 200
}

{
  "timestamp": "2026-05-12T05:19:08.238Z",
  "pano_id": 12955795,
  "duration_ms": 811.73,
  "db_time_ms": 88.95,
  "overhead_ms": 722.78,
  "host": "ip-10-1-16-24.ap-southeast-2.compute.internal"
}

동시간대 무거운 bulk 요청 로그:

{
  "timestamp": "2026-05-12T05:19:54.268Z",
  "endpoint": "PanosController#bulk",
  "duration_ms": 6885.74,
  "db_time_ms": 1366.28,
  "host": "ip-10-1-16-24.ap-southeast-2.compute.internal",
  "region": "ap-southeast-2"
}

관찰된 패턴:

• DB 시간은 평균 60-150ms로 전체 응답 시간(600-900ms)의 일부에 불과
• overhead (duration - db_time)가 일관되게 550-800ms — S3 I/O가 주원인
• ap-southeast-2의 두 호스트(ip-10-1-146-78, ip-10-1-16-24)에서 동시에 PanosController#bulk가 6.9초 소요되어 DB 커넥션 풀 경합 유발
• cupix-agent가 2초 간격으로 순차적 pano ID에 대해 반복 폴링 (배치 업로드 패턴)

us-west-2 리전 로그 (toyoeng, qatest3):

service:cupixworks-api "check_uploading" @duration:>500ms
Time: 2026-05-12T05:12:00Z ~ 2026-05-12T05:20:00Z

{
  "timestamp": "2026-05-12T05:19:40Z",
  "pano_ids": "84220913-84221066",
  "duration_range_ms": "601-728",
  "teams": ["toyoeng", "qatest3"],
  "region": "us-west-2"
}

us-west-2에서도 동일한 패턴으로 DB 시간은 낮지만 전체 응답이 600ms+ — 리전 무관한 체계적 문제 확인.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

set_pano before_action을 check_uploading에서 제외 (app/controllers/api/v1/panos_controller.rb:8):

• check_uploading은 pano의 upload 상태만 확인하면 되므로, 10+ JOIN이 포함된 set_pano 대신 가벼운 find(id) 쿼리로 대체해야 한다.
• except 목록에 check_uploading을 추가하고, 액션 내부에서 @model = Pano.find(params[:id])로 직접 로드하면 DB 시간을 60-150ms에서 10ms 이하로 줄일 수 있다.

단기 개선 (1주 이내)#

S3 HEAD 요청 최적화 (app/models/concerns/storagable/resource.rb:167):

• _object.exists? 호출에 타임아웃을 설정하여 느린 S3 응답이 전체 요청을 블로킹하지 않도록 한다.
• cupix-agent의 배치 업로드 폴링 시, 이미 uploaded 상태인 pano는 S3 확인을 건너뛰도록 check_resource_uploading!의 state guard를 활용한다 (현재 resource_state_name이 uploaded이면 건너뛰는 로직 존재).

장기 개선 (재발 방지)#

• 비동기 업로드 확인: S3 event notification + SQS를 활용하여 클라이언트 폴링 대신 서버 push 방식으로 업로드 완료를 감지하는 구조 전환.
• Lightweight endpoint 분리: check_uploading처럼 상태만 확인하는 엔드포인트는 default_joins 없이 최소한의 데이터만 로드하는 별도 쿼리 경로를 사용.
• Connection pool monitoring: 동시 bulk 요청과 폴링 요청이 겹칠 때 DB 커넥션 풀 고갈을 모니터링하는 알림 추가.

Monitoring#

• check_uploading p95 latency 알림:

avg(last_5m):trace.rack.request.duration{service:cupixworks-api, resource_name:api::v1::panoscontroller#check_uploading} > 500000000

• S3 HEAD request latency by endpoint:

avg:aws.s3.first_byte_latency{operation:head_object} by {host}

• 동시 bulk 요청 모니터링:

sum(last_5m):trace.rack.request.hits{service:cupixworks-api, resource_name:api::v1::panoscontroller#bulk}.as_count() > 10

Risk Assessment#

• Risk level: low — 기능적 오류는 없으며 모든 요청이 HTTP 200으로 정상 응답. 지연이 사용자 경험에 영향을 주지만 데이터 손실이나 처리 실패는 없다.
• 예상 복잡도: standard — set_pano except 추가는 단순 변경이나, S3 I/O 최적화는 스토리지 레이어 전반에 영향을 줄 수 있으므로 테스트 필요.