RCA: Api::V1::PanosController#stitched 지연 (avg 14954ms, max 15806ms)

Overview#

What Happened#

2026-06-29 16:48 KST에 cupixworks-api(us-west-2) 서비스의 PUT /api/v1/panos/:id/stitched 엔드포인트에서 평균 14.9초, 최대 15.8초에 달하는 지연이 3건 발생했다. 동일 시점에 cupix-agent가 동일 capture의 다수 pano에 대해 stitched 호출을 동시에 보내는 패턴이 관찰되었고, 로그상 db 시간만으로도 3.8~6.5초가 소비되었다. 응답은 HTTP 400 STAT10000 Pano already stitched (이미 stitched 상태인 pano에 대한 멱등 호출)로 종료되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-29 16:48 KST — 첫 지연 span 기록 (first_seen 07:48:44 UTC). 동일 capture의 여러 pano에 대해 cupix-agent가 stitched 호출을 동시 발사.
2. 2026-06-29 16:48 KST — 마지막 지연 span 기록 (last_seen 07:48:44 UTC).
3. 2026-06-29 16:49 KST — 동일 패턴의 슬로 요청 3건이 13.6~15.7s 소요 후 HTTP 400 Pano already stitched로 종료 (Datadog 로그 07:49:01.037Z, request_id f30193cc-eb24-4dad-b3a7-7671cb279f21 등).

Error Log#

Datadog Logs

resource_name: Api::V1::PanosController#stitched
service:       cupixworks-api
occurrences:   3
avg_ms:        14954
max_ms:        15806
sample_trace_id: 2516538677585389462

대표 요청 로그 (07:49:01.037Z, request_id f30193cc-eb24-4dad-b3a7-7671cb279f21):

{
  "message": "[400] PUT /api/v1/panos/90501479/stitched (Api::V1::PanosController#stitched)",
  "duration": 15703.32,
  "view": 0.11,
  "db": 6511.13,
  "error": {
    "reason": "Pano already stitched",
    "code": "STAT10000",
    "message": "Pano already stitched",
    "class": "Cupix::Errors::InvalidState"
  },
  "user_agent": "cupix-agent",
  "team": { "domain": "flintco", "id": 887 },
  "user": { "id": 49728, "email": "megan.bauknight@flintco.com" }
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 3
• 최초 발생: 2026-06-29 16:48 KST
• 최근 발생: 2026-06-29 16:48 KST
• 사용자 영향: cupix-agent 자동 처리 워크플로의 stitched 확인 단계가 요청당 15초까지 지연. 응답 자체는 멱등 검사 결과(400 already stitched)이므로 기능 실패는 아니나, agent 측에서 sync HTTP 호출을 직렬로 묶어두면 cumulative throughput이 떨어진다.

Root Cause Summary#

PUT /api/v1/panos/:id/stitched의 set_pano before_action이 PanoRepository.show(id)를 호출하면서 default_joins + permission_joins로 구성된 15개 이상의 LEFT JOIN 서브쿼리(review/capture/record/facility/workspace/team × user/group/system_group permission 매트릭스)를 단일 pano 조회에 대해 실행한다. 비싼 SELECT가 컨트롤러 액션 본문(PanoRepository#stitched 첫 줄의 Pano already stitched 멱등 검사)에 도달하기 전에 수 초를 소비하기 때문에, 검증이 항상 즉시 실패하는 케이스(이미 stitched된 pano)에도 동일한 풀-페이로드 권한 조인 비용이 발생한다. 로그상 db: 3843~6511ms 가 전체 duration의 핵심을 차지하며, view: 0.1ms로 렌더링 비용은 사실상 0이다. 동시간대에 다른 엔드포인트에서도 @db:>5000ms 가 관찰되어 DB 가 일부 압박을 받고 있었고, 그 위에 permission_joins의 무거운 비용이 누적되어 15초까지 늘어났다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/panos_controller.rb:128 (def stitched)
• Before-action: app/controllers/api/v1/panos_controller.rb:8, :141 (set_pano → repository_instance.show(params[:id]))
• Heavy SELECT: app/repositories/pano_repository.rb:116- (PanoRepository.permission_joins) + :76- (default_joins)
• Failure point (logical, not exception): app/repositories/pano_repository.rb:38 (raise InvalidState if @model.stitched?) — 무거운 SELECT가 끝난 뒤 첫 줄에서 즉시 400.

set_pano before_action 은 stitched 액션 전에 항상 실행된다:

before_action :set_pano, except: %i[index create bulk_update upload_candidates untrash purge show bulk mock nearest]

def stitched
  pano = repository_instance.stitched(
    original_panorama_format: params.require(:original_panorama_format)
  )

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

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

PanoRepository.show (상속받은 BaseRepository.show) 는 current_user 가 있으면 항상 permission_joins(default_joins(...)) 경로를 탄다:

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

default_joins 는 panos 에 storage, capture, level, record, facility, workspace, team, clusters, masks, capture_types, cameras 를 조인하여 30+ 컬럼을 SELECT 한다:

def self.default_joins(record)
  record.includes(:storage).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('

permission_joins 는 15개 이상의 권한 서브쿼리를 LEFT JOIN 한다:

record.joins("
  LEFT JOIN (
    SELECT reviews.id AS review_id, 2 AS permission
    FROM reviews
    where reviews.public_access_enabled_at IS NOT NULL
      AND reviews.id = #{sanitized_review_id}
  ) AS review_public_permissions
    ON review_public_permissions.review_id = #{sanitized_review_id}

  LEFT JOIN (
    SELECT review_id, permission
    FROM review_permissions
    ...
  ) AS review_user_permissions
  ...
  LEFT JOIN (
    SELECT capture_id, permission
    FROM capture_permissions
    WHERE capture_permissions.accessor_id = #{sanitized_user_id}
      AND capture_permissions.accessor_type = 'User'
    ) AS capture_user_permissions
      ON capture_user_permissions.capture_id = panos.capture_id
  ...

PanoRepository#stitched 의 첫 줄이 멱등 검사이므로, 이미 stitched 된 pano 에 대해서도 위의 비싼 조인이 항상 선행 실행된다:

def stitched(params = {})
  raise Cupix::Errors::InvalidState.new(code: 'STAT10000', reason: 'Pano already stitched') if @model.stitched?

  @model.update!(
    stitched: true,
    original_panorama_format: params[:original_panorama_format]
  )

  @model.shift_stitched_panorama! if @model.resource_shift_eligible?

  @model
end

기대 동작: 멱등 검사 실패는 수십수백 ms 안에 4xx 로 반환되어야 한다. 실제 동작: set_pano 의 permission_joins 가 3.86.5s 의 DB 시간을 소비하고, 그 위에 connection acquisition / GC / 동시 요청에 의한 자원 경쟁이 더해져 13.6~15.7s 의 wall time 으로 끝난다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "Api::V1::PanosController#stitched" @duration:>10000

service:cupixworks-api "PanosController#stitched" @duration:>14000

service:cupixworks-api @db:>5000  (시간 범위 2026-06-29T07:30:00Z ~ 08:10:00Z)

대표 슬로 요청 3건 (모두 동일 capture 의 인접 pano ID, 동일 user/team, 동일 millisecond 타임스탬프):

[
  {
    "timestamp": "2026-06-29T07:49:01.037Z",
    "message": "[400] PUT /api/v1/panos/90501472/stitched",
    "duration": 13680.73,
    "db": null,
    "error": { "code": "STAT10000", "reason": "Pano already stitched" }
  },
  {
    "timestamp": "2026-06-29T07:49:01.037Z",
    "message": "[400] PUT /api/v1/panos/90501479/stitched",
    "duration": 15703.32,
    "db": 6511.13,
    "error": { "code": "STAT10000", "reason": "Pano already stitched" }
  },
  {
    "timestamp": "2026-06-29T07:49:01.037Z",
    "message": "[400] PUT /api/v1/panos/90504092/stitched",
    "duration": 15147.0,
    "db": 3843.52,
    "error": { "code": "STAT10000", "reason": "Pano already stitched" }
  }
]

같은 시간대 다른 엔드포인트도 @db:>5000ms 발생 (예시):

2026-06-29T08:09:41.814Z  [200] PUT /api/v1/element_traces       Api::V1::ElementTracesController#bulk
2026-06-29T08:09:31.810Z  [200] POST /api/v1/admin/access_codes  Api::V1::Admin::AccessCodesController#create
2026-06-29T08:09:11.805Z  [200] POST /api/v1/authenticate        Api::V1::AuthenticatesController#create

→ DB가 전반적으로 무거운 시간대였고, 그 부하 위에 permission_joins 가중 비용이 얹혀 stitched 가 가장 큰 영향을 받았다.

호출자 컨텍스트: 같은 2시간 윈도우 동안 cupix-agent user_agent 의 stitched 호출이 100건 이상 수집됨 (rate-limit 미적용 추정):

service:cupixworks-api "Api::V1::PanosController#stitched" @user_agent:cupix-agent  (now-2h, 100건 hit)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• PanoRepository#stitched 의 멱등 빠른 경로 추가: app/repositories/pano_repository.rb:38 의 @model.stitched? 검사를 set_pano 단계에서 permission_joins 없이 우선 확인할 수 있도록, stitched 액션 한정으로 repository_instance.show(id, skip_permission: true) + 가벼운 권한 가드를 사용하거나, before_action 에서 panos.id, panos.stitched 컬럼만 select 하는 별도 lookup 을 도입한다. 이렇게 하면 already-stitched 케이스는 100ms 미만으로 종료된다.
  • 근거: db: 6511ms 의 거의 전부가 permission_joins SELECT 1회 (pano_repository.rb:159-215). 멱등 분기는 권한 평가 이전에 결정 가능.
• 재시도 폭주 완화: cupix-agent 측에서 Pano already stitched 응답을 받았을 때 즉시 다음 단계로 진행하도록 호출 패턴을 점검 (이미 stitched 라면 재호출 자체가 불필요). 동시간대에 동일 user_agent 가 단일 ms 에 다수 호출을 보내는 패턴이 확인됨.

단기 개선 (1주 이내)#

• permission_joins SQL 최적화: app/repositories/pano_repository.rb:116-215 의 15+ LEFT JOIN 서브쿼리는 GREATEST/MAX 누적용으로 작성되어 있어 인덱스 활용이 어렵다. 단일 pano 조회용으로는 (1) 권한 평가를 별도 Pundit policy 호출로 분리하고, (2) default_joins/permission_joins 는 index/search 용도로만 사용하는 방향을 검토한다.
• stitched 액션 분리: write 작업 (@model.update!, shift_stitched_panorama!) 의 비용과 read/permission 의 비용을 분리. write 경로에서는 pano + capture + team 만 필요.
• APM 스팬 세분화: set_pano / permission_joins / stitched repository call / shift_stitched_panorama! 각각을 별도 custom span 으로 감싸 어디서 시간이 소비되는지 트레이스에서 즉시 보이게 한다.

장기 개선 (재발 방지)#

• stitched 처리의 비동기화: 현재 shift_stitched_panorama! 는 S3 object.copy_to 를 동기로 수행 (app/models/concerns/resourcable/pano.rb:153). agent 가 대규모 batch 처리 중일 때 이 동기 IO 가 누적되면 connection pool 압박을 키운다. 200/202 + worker 위임 패턴 도입을 검토.
• 권한 모델 정규화: permission_joins 가 review/capture/record/facility/workspace/team × user/group/system_group 까지 매트릭스로 펼쳐진 구조가 모든 read API 에 침투해 있어 잠재 risk 가 크다. denormalized permission cache 테이블 또는 materialized view 검토.

Monitoring#

writing-datadog-monitoring-queries 가이드에 맞춰 dashboard timeseries widget 에서 그래프로 렌더 가능한 쿼리만 사용한다.

• p95 latency of stitched endpoint (밀리초):

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::PanosController#stitched,env:production}

• stitched endpoint hit rate by status code:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::PanosController#stitched,env:production} by {http.status_code}.as_rate()

• "Pano already stitched" (멱등 실패) 발생률:

sum:logs.hits{service:cupixworks-api,@error.code:STAT10000,@controller:Api::V1::PanosController,@action:stitched}.as_count()

• DB time share for stitched (avg ms):

avg:trace.rack.request.duration.by.resource_service.db{service:cupixworks-api,resource_name:Api::V1::PanosController#stitched,env:production}

알림: Api::V1::PanosController#stitched p95 가 5초를 5분 이상 초과하면 page (현재 환경상 평시 p95는 sub-1s 이어야 함 — 14s avg 는 명백한 abnormal).

Risk Assessment#

• Risk level: medium — 기능 결과는 정상(멱등 실패는 의도된 동작)이나 자동화 agent 호출 throughput 을 크게 떨어뜨리고 동일 패턴이 high-volume capture upload 마다 재현 가능.
• 예상 복잡도: standard — 멱등 fast-path 도입은 routing/before_action 수준 변경으로 가능. permission_joins 자체 리팩토링은 critical (광범위 영향).