RCA: Api::V1::LevelsController#merged_voxels (avg 64491ms, max 65435ms)

Overview#

What Happened#

2026-06-25 00:22 ~ 00:27 KST 동안 cupixworks-api(us-west-2) 의 Api::V1::LevelsController#merged_voxels 엔드포인트가 평균 64.5초, 최대 65.4초 latency 로 6회 응답했다. 모든 슬로우 요청은 동일한 level_id=55514(team swinerton) 을 대상으로 했으며, 응답 자체는 HTTP 302(/merge 결과 signed S3 URL 로 redirect) 로 정상 처리되었다. 지연 시간의 거의 전부는 controller 가 동기 호출하는 외부 voxel-service /merge 엔드포인트에서 소비되었다.

Quick Facts#

Affected Teams#

다른 level (72845, 13096, 72827, 55168) 의 동일 엔드포인트 호출은 같은 윈도우에서 1초 내외로 정상 처리됨 — 영향은 단일 level 에 집중.

Timeline#

1. 2026-06-25 00:20:23 KST — level_id=55514 첫 호출 (이미 슬로우 시작).
2. 2026-06-25 00:22:02 KST — first_seen. cluster 윈도우 시작, 64s 응답 다수.
3. 2026-06-25 00:23:09 ~ 00:27:22 KST — 동일 level 에 대해 6건의 64s 요청 발생 (cluster 본체).
4. 2026-06-25 00:28:22 KST — 64.4s 추가 발생 (윈도우 외).
5. 2026-06-25 00:28:35 KST — 같은 level 호출이 427ms 로 완료 — Rails Rails.cache.fetch(..., expires_in: 30.seconds) 캐시 히트로 추정됨.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::LevelsController#merged_voxels",
  "service": "cupixworks-api",
  "occurrences": 6,
  "avg_ms": 64491,
  "max_ms": 65435,
  "sample_trace_id": "3886141582058782715"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 6
• 최초 발생: 2026-06-25 00:22 KST
• 최근 발생: 2026-06-25 00:27 KST

Root Cause Summary#

Api::V1::LevelsController#merged_voxels 는 controller 안에서 Cupix::VoxelService.merge_voxel 을 동기 호출하고, 그 안에서 다시 Cupix::HttpClient.put 으로 외부 voxel-service /merge 엔드포인트를 호출한 뒤 signed S3 URL 로 redirect 한다. level_id=55514 처럼 capture/pointcloud 수가 많은 level 의 경우 voxel-service 의 merge 처리 자체가 ~60초가 걸리며, 이 시간 전부가 Rails request thread 에서 대기로 소비된다. Rails.cache.fetch(... expires_in: 30.seconds) 로 결과를 캐싱하지만 캐시 TTL(30s) 이 단일 처리 시간(~64s) 보다 짧아, 첫 요청이 끝나기도 전에 두 번째 요청이 같은 cache key 에 대해 또 다시 미스로 들어가고, TTL 이 만료되면 다시 cold compute 가 일어난다. 결과적으로 동일 level 에 대한 연속 호출이 캐시의 보호를 받지 못하고 모두 ~64초 latency 를 겪는다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/concerns/voxels_controller.rb:16 (merged_voxels action)
• Param 빌드: app/repositories/concerns/voxels_repository.rb:39 (create_merge_voxel_params! — capture_ids, pointcloud_ids 를 모두 pluck)
• Failure (latency) point: app/services/cupix/voxel_service.rb:60 (Cupix::HttpClient.put("#{$CUPIX_VOXEL_SERVICE_URL}/merge", ...)) — 외부 서비스 호출이 ~64초 블로킹.
• Cache layer: app/services/cupix/voxel_service.rb:52 — Rails.cache.fetch(cache_key, expires_in: 30.seconds).

def merged_voxels
  raw_access_token = request.headers['X-CUPIX-AUTH'] || params['x-cupix-auth']
  merge_voxel_params = repository_instance.create_merge_voxel_params!(params)

  if merge_voxel_params[:capture_ids].blank? && merge_voxel_params[:pointcloud_ids].blank?
    render body: 'x,y,z,w,voxel_size', status: :ok
  else
    redirect_to Cupix::VoxelService.merge_voxel(merge_voxel_params.merge('x-cupix-auth' => raw_access_token)), allow_other_host: true
  end
end

def merge_voxel(params = {})
  access_token = params.delete('x-cupix-auth')
  cache_key = merge_voxel_cache_key(params)

  Rails.cache.fetch(cache_key, expires_in: 30.seconds) do
    headers = {
      'Content-Type': :json,
      'x-cupix-auth': access_token
    }
    body = params.to_json

    begin
      response = Cupix::HttpClient.put("#{$CUPIX_VOXEL_SERVICE_URL}/merge", body, headers)

      body = JSON.parse(response.body)

      body['signed_url']
    rescue RestClient::Exception => e
      ...
    end
  end
end

Cupix::HttpClient.put 는 timeout 옵션 없이 RestClient.put 만 호출하기 때문에 RestClient 의 default 동작(사실상 매우 큰 timeout) 으로 voxel-service 가 응답을 줄 때까지 무한정 대기한다.

def self.put(url, payload, headers = {}, retries: MAX_RETRIES)
  attempt = 0
  begin
    RestClient.put(url, payload, headers)
  rescue RestClient::Exception => e
    if RETRIABLE_STATUS_CODES.include?(e.http_code) && attempt < retries
      attempt += 1
      sleep((2**(attempt - 1)) + rand(0.0..0.5))
      retry
    end
    raise
  end
end

기대 동작: voxel-service 가 빠르게 signed S3 URL 을 반환 → 사용자는 redirect 후 S3 에서 CSV 다운로드. 실제 동작: voxel-service /merge 가 level 55514 의 capture/pointcloud 셋을 처리하는 데 ~64초 소요 → Rails request thread 가 그동안 점유됨. 캐시 TTL(30s) 이 처리 시간(~64s) 보다 짧아 cache stampede 가 사실상 매번 발생.

Log Evidence#

Datadog query:

service:cupixworks-api "merged_voxels"

Time window: 2026-06-24T15:22:00Z ~ 2026-06-24T15:28:00Z (= 2026-06-25 00:22 ~ 00:28 KST).

같은 윈도우 안에서 level 별 latency 가 극단적으로 갈림 (raw 로그의 attributes.duration 필드, ms 단위):

대표 raw log 항목 (level 55514, duration 63983.6ms, status 302):

{
  "timestamp": "2026-06-24T15:27:22.275Z",
  "message": "[302] GET /api/v1/levels/55514/voxels (Api::V1::LevelsController#merged_voxels)",
  "status": "info",
  "duration": 63983.6,
  "db": 12.19,
  "controller": "Api::V1::LevelsController",
  "action": "merged_voxels",
  "params": { "record_id": "131059", "id": "55514" },
  "team": { "domain": "swinerton", "id": 527 },
  "http": {
    "url_details": { "path": "/api/v1/levels/55514/voxels" },
    "status_code": 302,
    "method": "GET"
  },
  "location": "https://cupix-cupixworks-prod-data-stage-uswe2.s3.amazonaws.com/voxel/facility_key%3D4p35b3/model_id%3D55514/model_type%3Dlevel/a3497fda-737d-44c9-aca0-ed98c6affd5b.csv",
  "tags": ["env:production", "region:us-west-2", "version:production-us-west-2-20260624t0507z0-24b9962e-cupixworks"]
}

핵심 관찰:

• 동일 윈도우에서 다른 level (72845, 13096, 72827, 55168) 의 merged_voxels 호출은 모두 0.4 ~ 2초 안에 완료. → Rails 자체나 us-west-2 region 전반의 문제는 아님.
• 모든 슬로우 요청이 level_id=55514(swinerton) 한 곳에 집중. → level-specific data volume issue.
• DB time 은 db: 12.19ms 로 무시 가능. → DB cluster, AR 쿼리 문제 아님. 시간은 외부 HTTP 호출에서 소비.
• 응답은 status 302 정상. error/warn 로그 없음 (service:cupixworks-api status:(warn OR error) "voxel" 동일 윈도우 결과 0건).
• 00:28:35 KST 의 427ms 응답은 직전 00:28:22 의 64s cold-compute 가 캐시를 채워놓은 결과로 해석됨 (Rails.cache.fetch 30s TTL 안에 들어옴).
• 동일 윈도우의 service:voxel-service 로그 검색 결과 0건 — voxel-service 는 Datadog 의 동일 collector 로 로깅하지 않거나 다른 service 이름을 사용함. → voxel-service 측 검증은 별도 채널 필요 (uncertain — needs verification).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• HTTP timeout 설정: lib/cupix/http_client.rb:48-68 (self.put) 및 다른 메서드들의 RestClient.put/post/get 호출에 명시적 timeout: … 옵션을 추가해야 한다. 현재 timeout 이 없어 voxel-service 가 응답하지 않으면 Rails worker 가 무기한 점유될 수 있다. 우선은 voxel-service /merge 호출 부분(app/services/cupix/voxel_service.rb:60) 에 합리적인 read timeout (예: 30s) 을 적용하고, timeout 발생 시 사용자에게 적절한 5xx 또는 "처리 중" 상태로 응답하는 방향이 필요하다.
• 클라이언트 사용 패턴 점검: 같은 level 에 대해 0.5 ~ 1분 사이 여러 번 GET 이 들어오는 패턴이 보임 (level 55514 의 00:23, 00:24, 00:25, 00:26, 00:27 KST). 프론트엔드의 polling/retry 동작인지, 사용자가 새로고침을 반복하고 있는지 확인 필요. 만약 polling 이라면 앞 요청이 in-flight 일 때 추가 요청을 막거나 backoff 를 적용한다.

단기 개선 (1주 이내)#

• 캐시 TTL 재조정: app/services/cupix/voxel_service.rb:52 의 expires_in: 30.seconds 를 평균 처리 시간보다 길게 (예: 5~10분) 늘리고, capture/pointcloud 셋이 변경되면 cache 를 명시적으로 invalidate 하도록 한다 (이미 remove_cached_merged_voxels 가 존재하므로 이를 변경 시점에 호출). 현재 30초 TTL 은 64초 짜리 작업에 대해 의미가 거의 없다.
• dogpile / single-flight: cold compute 동안 동일 cache key 의 다른 요청이 같이 미스로 들어가 voxel-service 를 중복 호출하는 것을 막기 위해 Rails.cache.fetch(..., race_condition_ttl:) 또는 별도 분산 lock(Redis SETNX) 으로 single-flight 패턴을 적용한다.
• 비동기화 후보: merged_voxels 가 사용자 인터랙티브 경로면, "redirect 직접 반환" 대신 "in-progress 응답 + worker 처리 후 callback/polling" 구조로 변경하는 것이 근본적 개선. 현재 GET 요청이 60초 이상 블록되는 패턴은 LB/CDN 의 idle timeout 위험도 동반한다.

장기 개선 (재발 방지)#

• voxel-service /merge 자체의 처리 시간 단축: capture/pointcloud 가 많은 level 에 대해 부분 캐시 / 파티션별 사전 머지 / 결과 보관(S3 ETag 기반 conditional regenerate) 등 voxel-service 측 최적화. 현재 add_partition, remove_cache! 같은 partition-aware API 가 이미 존재하므로 이를 활용해 incremental merge 로 전환 가능한지 검토.
• APM-based latency SLO: resource_name:Api::V1::LevelsController#merged_voxels 에 대해 p95 SLO 와 알람을 설정해 동일 패턴 재발 시 빠르게 감지.
• LB/Nginx idle timeout 검토: 현재 max 65.4s 가 실제로 응답되었다는 것은 인프라 전체 타임아웃이 65s+ 라는 뜻. 이는 다른 정상 트래픽도 같은 라인 뒤에서 밀릴 수 있어 검토 필요.

Monitoring#

추가/검토할 메트릭:

• Api::V1::LevelsController#merged_voxels p95 / p99 latency
• voxel-service /merge request count + p95 (외부 호출 측에서 별도 트래킹)
• cache hit ratio (가능하면 Rails.cache 키 스코프별)

Datadog 쿼리 예시 (각 라인은 release dashboard timeseries widget 그대로 사용 가능):

avg:trace.rack.request.duration.by.resource_service.95p{service:cupixworks-api,resource_name:api::v1::levelscontroller#merged_voxels,env:production}

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::levelscontroller#merged_voxels,env:production}.as_count()

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#merged_voxels,env:production}

(metric 이름은 환경에 따라 trace.rails.request.* 또는 trace.rack.request.* 일 수 있음 — 대시보드 적용 시 실제 메트릭 카탈로그로 확인.)

Risk Assessment#

• Risk level: medium — 사용자 응답이 실패하지 않고 status 302 로 정상 마무리되지만 60초 대기는 제품 체감상 사실상 장애. 동시에 Rails worker 가 60초 이상 점유되어 다른 트래픽을 잠식할 위험이 있어 단순 UX 문제가 아님.
• 예상 복잡도:
  • HTTP timeout 추가: trivial.
  • 캐시 TTL/invalidation 재설계: standard.
  • merged_voxels 비동기화 또는 voxel-service 처리 시간 단축: critical (서비스 간 계약 변경 가능).