ES /docs

Api::V1::CapturesController#index (avg 10022ms, max 10022ms)

RCA: Api::V1::CapturesController#index slow response (avg 10022ms)

Overview#

What Happened#

2026-06-27 12:28 KST에 cupixworks-api 의 Api::V1::CapturesController#index 엔드포인트에서 단일 요청이 10,022ms (약 10초) 소요되었다. APM trace 6349853460116089336 한 건이 latency 임계치를 초과하여 클러스터로 분류되었고, 동일 시간대(±15분) 다른 /api/v1/captures 요청은 모두 정상 응답(200)이어서 일시적 slow path 로 보인다.

Quick Facts#

Field Value
resource_name Api::V1::CapturesController#index
service cupixworks-api
sample_trace_id 6349853460116089336
avg_duration_ms 10022
max_duration_ms 10022
occurrence_count 1
region us-west-2
tenant cupix
env production

Affected Teams#

Team / Domain Error Count Impact
cupixworks-api /api/v1/captures consumers 1 단일 요청 10초 대기 — 사용자 수동 재시도 가능, 다른 동시 요청에 영향 없음

영향 범위 추가 식별 불가 — 단일 trace 만 기록됨.

Timeline#

  1. 2026-06-27 12:28 KST — GET /api/v1/captures 요청 진입, trace_id 6349853460116089336 시작
  2. 2026-06-27 12:28 KST + 10022ms — 요청 종료 (latency cluster 첫 감지, first_seen=last_seen)
  3. 2026-06-27 12:28~13:21 KST — 동일 endpoint 다른 요청은 200 응답으로 정상 (Datadog 로그 확인)

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::CapturesController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10022,
  "max_ms": 10022,
  "sample_trace_id": "6349853460116089336"
}

이 cluster 는 error 가 아닌 latency cluster 다. 별도 exception/stack trace 는 없다.

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1
  • 최초 발생: 2026-06-27 12:28 KST
  • 최근 발생: 2026-06-27 12:28 KST

Root Cause Summary#

Api::V1::CapturesController#index 는 CaptureRepository#search 를 호출하며, 내부적으로 (1) filter_by_processing_state 등 RDB(MySQL) pluck 쿼리, (2) current_user.readable_record_ids / directly_accessible_capture_ids 등 권한 확인 쿼리, (3) Elasticsearch Capture.search 쿼리, (4) ES 결과에 대한 permission_joins LEFT JOIN(15+) SQL 쿼리를 순차적으로 실행한다. 단일 요청이 10,022ms 로 정확히 ~10초 임계 부근에 머문 점, 그리고 동시간대 다른 요청은 정상이었던 점으로 보아 이번 cluster 의 root cause 는 특정 요청의 query_option 조합이 ES 또는 권한 LEFT JOIN SQL 의 cold/heavy path 를 트리거한 일회성 slow query 로 추정된다. 단일 trace, 별도 application 로그 부재로 정확한 bottleneck (ES vs SQL) 은 미확정이며 추가 APM span 데이터가 필요하다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/captures_controller.rb:22

app/controllers/api/v1/captures_controller.rb:22-38ruby
def index
  capture_query_option = Cupix::QueryOption::Capture.new(get_query_option, params)
  captures = repository_instance.search(capture_query_option)

  if MidasOperation.enabled? && Cupix::Tesla.launch_mode == 'CUPIXVISTA' && captures.contents.present?
    capture_ids = captures.contents.map(&:id)
    purchased_map = MidasOperation.check_captures_purchased(capture_ids: capture_ids)
    @serializer_option[:params] ||= {}
    @serializer_option[:params][:purchased_map] = purchased_map
  end

  render_api Renderable.new({
    search_result: captures,
    is_collection: true,
    serializer_option: @serializer_option
  })
end

repository_instance.search 는 BaseRepository#search → CaptureRepository#_search 로 위임된다.

CaptureRepository#_search 는 ES 호출 이전에 여러 차례 MySQL pluck 쿼리 를 수행한다:

app/repositories/capture_repository.rb:662-695ruby
if self.current_user.present?
  self.query_option.query[:bool][:must] += [
    {
      bool: {
        should: [
          {
            terms: {
              "record.id": self.current_user.readable_record_ids
            }
          },
          {
            terms: {
              id: self.current_user.directly_accessible_capture_ids
            }
          }
        ]
      }
    }
  ]
end

filter_by_spacetime_id(self.query_option)
filter_by_processing_state(self.query_option)
filter_by_user(self.query_option)
filter_by_summary(self.query_option)
filter_invalid_capture(self.query_option)
filter_by_creation_platform(self.query_option)

response = ::Capture.search(
  self.query_option.serializable_hash
).paginate(
  per_page: self.query_option.per_page,
  page: self.query_option.page
)

filter_by_processing_state 는 processing_state 파라미터가 있을 경우 captures 테이블에 대해 최대 3개의 where(...).pluck(:id) 쿼리를 실행하고 결과 id 목록을 ES terms 절에 임베드한다:

app/repositories/capture_repository.rb:793-839ruby
def filter_by_processing_state(query_option)
  return if query_option.processing_state.blank?

  processing_states = Array(query_option.processing_state.split(',').map(&:strip))
  query = ::Capture.where(trashed_at: nil)

  capture_ids = []

  if processing_states.include?('ready')
    ready_ids = query.where(
      upload_state: 'upload_done',
      state: 'done',
      reconstruction_state: 'done'
    ).pluck(:id)
    capture_ids += ready_ids
  end

  if processing_states.include?('processing')
    processing_ids = query.where(
      upload_state: %w[pano_uploading upload_ready reset upload_pending upload_done],
      state: %w[created initializing uploading upload_ready ready_to_process queued processing finalizing moving done],
      reconstruction_state: %w[processing none],
      error_code: nil
    ).pluck(:id)
    capture_ids += processing_ids
  end

  if processing_states.include?('error')
    error_ids = query.where(upload_state: 'invalid').pluck(:id)
    error_ids += query.where(state: %w[invalid error]).pluck(:id)
    error_ids += query.where(reconstruction_state: 'error').pluck(:id)
    error_ids += query.where.not(error_code: nil).pluck(:id)
    capture_ids += error_ids.uniq
  end

  capture_ids = capture_ids.uniq
  if capture_ids.present?
    query_option.query[:bool][:must] << {
      terms: { id: capture_ids }
    }
  else
    query_option.query[:bool][:must] << { match_none: {} }
  end
end

ES 호출 이후 BaseRepository#search 는 ES 가 돌려준 record id 들에 permission_joins 의 15+ LEFT JOIN subquery 를 다시 적용한다:

app/repositories/capture_repository.rb:322-471ruby
record.joins("
  LEFT JOIN ( ... ) AS review_public_permissions ON ...
  LEFT JOIN ( ... ) AS review_user_permissions ON ...
  LEFT JOIN ( ... ) AS review_group_permissions ON ...
  LEFT JOIN ( ... ) AS capture_user_permissions ON ...
  LEFT JOIN ( ... ) AS record_user_permissions ON ...
  LEFT JOIN ( ... ) AS record_group_permissions ON ...
  LEFT JOIN ( ... ) AS record_system_group_permissions ON ...
  LEFT JOIN ( ... ) AS facility_user_permissions ON ...
  LEFT JOIN ( ... ) AS facility_group_permissions ON ...
  LEFT JOIN ( ... ) AS facility_system_group_permissions ON ...
  LEFT JOIN ( ... ) AS workspace_user_permissions ON ...
  LEFT JOIN ( ... ) AS workspace_group_permissions ON ...
  LEFT JOIN ( ... ) AS team_user_permissions ON ...
  LEFT JOIN ( ... ) AS team_group_permissions ON ...
  LEFT JOIN ( ... ) AS team_system_group_permissions ON ...
").group('id').select(_select).where(...)

Failure point: 정확한 bottleneck span 은 단일 trace 만으로는 미확정. 후보는 다음 중 하나 또는 조합:

  1. ::Capture.search(...) ES query — readable_record_ids / directly_accessible_capture_ids 가 매우 클 때 ES bool/terms 절이 거대해져 ES coordinating node 가 ~10초 소요
  2. permission_joins LEFT JOIN 체인 — 15+ subquery 가 inner table scan 으로 fallback 되는 plan
  3. current_user.readable_record_ids / directly_accessible_capture_ids pluck — 권한 그래프가 큰 tenant 의 경우 단독으로 다수의 SQL 수행
  4. Ruby GC / 외부 dependency (Elasticsearch 노드 GC pause, RDS replica lag spike)

기대 동작: /api/v1/captures 은 보통 100~500ms 이내 응답해야 함 (동시간대 다른 요청 모두 200 정상). 실제 동작: 한 요청에서만 10022ms 소요.

Log Evidence#

사용한 Datadog 쿼리:

text
service:cupixworks-api "Api::V1::CapturesController#index"

동시간대 index 요청 로그 — 모두 정상 (status 200, 1초 이내 응답으로 추정되는 일반 트래픽):

text
2026-06-27 13:21:01  [200] GET /api/v1/captures (Api::V1::CapturesController#index)
2026-06-27 13:20:51  [200] GET /api/v1/captures (Api::V1::CapturesController#index)
2026-06-27 13:20:27  [200] GET /api/v1/captures (Api::V1::CapturesController#index)
...
2026-06-27 13:16:41  [200] GET /api/v1/captures (Api::V1::CapturesController#index)

trace_id 로 직접 검색한 결과는 비어 있음:

text
query: service:cupixworks-api 6349853460116089336
result: Found 0 logs

→ Datadog logs 에는 이 trace 의 controller 로그가 검색되지 않아 응답 status(200/5xx 여부) 와 query parameter 를 확인할 수 없다. APM trace 본문에는 SQL/ES span 이 남아 있을 가능성이 있으므로 Datadog APM UI 의 trace 6349853460116089336 flame graph 를 직접 확인해야 한다 — uncertain, needs verification.

Status board 컨텍스트:

text
scope: svc:cupixworks-api::unknown
active: null
recent: 8건 (6-24 ~ 6-27, 모두 root_cause_types=["unknown"])

cupixworks-api 에 unknown 타입 latency/error cluster 가 최근 며칠 반복적으로 발생 중. 동일 endpoint 의 latency 패턴은 이 cluster 가 처음이지만, 재발성을 가진 서비스 전반의 간헐 slow path 가능성 시사.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 일회성 slow ES/SQL path (특정 query_option 조합으로 cold cache 또는 큰 id 리스트 임베드) 단일 trace, 동시간대 다른 요청은 200; _search 가 다수 SQL pluck 후 ES + 15+ LEFT JOIN 체인을 수행하는 무거운 path; latency ≈ 10s 는 ES coordinating timeout 부근 trace 본문 span breakdown 미확보 (single trace logs 검색 0건) Confirmed (top hypothesis), 단 정확한 bottleneck span 은 needs verification
H2 외부 의존성(Elasticsearch / RDS) 광역 outage cluster_type: latency, ~10s 정확히 timeout 같은 값 Status board dep:* active 없음, 동시간대 다른 captures 요청은 정상, 다른 service 에 spillover 없음 Rejected
H3 Application bug 로 인한 무한 루프 / N+1 폭주 코드상 processing_state 분기에서 pluck 반복, permission_joins LEFT JOIN 다수 동일 endpoint 의 다른 요청은 정상이므로 일반적인 N+1 코드 버그가 아님 (입력 조합에 따른 worst-case) Rejected (as primary cause)
H4 Puma worker / Ruby GC stop-the-world pause 외부 메트릭 없음 직접 증거 없음, 동시 다른 요청은 정상이라 worker pause 도 약함 Inconclusive

Fix Recommendation#

즉시 조치 (Critical)#

  • 단일 occurrence cluster 이므로 즉시 코드 수정은 불필요. 다음 정보를 먼저 수집:
    1. Datadog APM UI 에서 trace 6349853460116089336 을 열어 SQL/ES span breakdown 을 확인 — 어느 span 이 ~10s 인지 식별 (app/controllers/api/v1/captures_controller.rb:22-38 범위)
    2. 동일 trace 의 request params (query_option) 를 확인 — processing_state, review_key, facility_key, spacetime_id, clustering_precision 등 어느 조합인지 기록

단기 개선 (1주 이내)#

  • app/repositories/capture_repository.rb:793-839 (filter_by_processing_state): processing_states 조합마다 별도 SQL pluck 를 수행 후 결과 id 들을 ES terms 절에 임베드한다. id 개수가 큰 tenant 에서는 ES request body 비대화로 ES coordinating overhead 가 커진다. SQL 에서 pluck 한 결과를 ES terms 로 넘기는 대신 ES 인덱스에 동일 컬럼(upload_state, state, reconstruction_state, error_code)을 두고 ES 단에서 필터하도록 재설계 검토.
  • app/repositories/capture_repository.rb:279-505 (permission_joins): 15+ LEFT JOIN subquery 체인은 query planner 가 hash join 대신 nested loop 로 빠지면 단독으로 수 초 단위 latency 를 만들 수 있다. EXPLAIN 으로 최악 query plan 을 확인하고, 필요 시 권한 결과를 별도 캐시(Redis) 또는 materialized view 로 분리 검토.
  • Api::V1::CapturesController#index 단계별 timing 을 Cupix::Logger.info 또는 Datadog::Tracing.trace custom span 으로 계측 (#index, _search, permission_joins, permission_filter 4 구간) 하여 다음 발생 시 즉시 bottleneck 식별 가능하도록 한다.

장기 개선 (재발 방지)#

  • captures 검색의 권한 모델을 read-time JOIN 에서 write-time 비정규화(예: ES 문서에 accessible_user_ids 필드 미리 채움)로 전환하면 permission_joins 비용을 제거할 수 있다. 단, 권한 변경 시 reindex 비용 trade-off 확인 필요.
  • cupixworks-api 의 svc:unknown cluster 가 최근 며칠간 반복 발생 중이므로 (status board 결과 참조) 서비스 레벨 P99 latency SLO 와 endpoint 별 anomaly 알림 도입.

Monitoring#

추가/확인할 Datadog 쿼리:

text
trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::CapturesController#index}.as_rate()
text
p99:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::CapturesController#index}
text
sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::CapturesController#index,@duration:>5s}.as_count()
text
avg:trace.elasticsearch.query.duration{service:cupixworks-api,resource_name:Api::V1::CapturesController#index}

알림 권장:

  • Api::V1::CapturesController#index p99 > 3s 가 5분 연속 시 warn
  • 동 endpoint 의 duration > 10s 트레이스가 5분간 ≥1건 발생 시 알림 (현재 cluster 와 동일 임계)

Risk Assessment#

  • Risk level: low (단일 occurrence, 동시간대 다른 요청은 정상, 사용자 영향 1건)
  • 예상 복잡도: standard (즉시 수정 없음, 후속 계측 추가 및 trace span 분석 필요)