RCA: Api::V1::PanosController#index latency (avg 31s, max 93s)

Overview#

What Happened#

2026-06-25 00:06 KST부터 09:21 KST 사이 us-west-2 production cupixworks-api의 Api::V1::PanosController#index 트레이스가 평균 31s, 최대 93s 까지 늘어졌다. 같은 시간대에 cupixworks-api 서비스 전체 평균 응답시간이 평소 ~0.1s에서 ~0.5s로 상승했고, Elasticsearch 쿼리 평균 시간도 0.05s → 0.37s로 약 7배 증가했다. 트레이스 19건, 단일 endpoint(Api::V1::PanosController#index) 단일 region(us-west-2)에서 관측된 latency 클러스터다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-25 00:06 KST — 첫 slow trace 관측 (cluster first_seen)
2. 2026-06-25 01:45 KST — status-board가 svc:cupixworks-api::unknown 인시던트 자동 개설 (관련 cluster 7건 누적, incident 2026-06-24-svc-cupixworks-api--unknown-2)
3. 2026-06-25 02:45–02:59 KST — Pano/Record/Capture ES _update_document에서 "NotFound - attributes_in_database" warn 폭증 (수백 건/분), 동시간대 ES query duration 평균 0.05s → 0.37s
4. 2026-06-25 02:59 KST — status-board 인시던트 자동 resolve
5. 2026-06-25 09:21 KST — 마지막 slow trace 관측 (cluster last_seen); 이후 ES 평균 latency 점진 회복 (~0.1s)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::PanosController#index",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 12683,
  "max_ms": 13216,
  "sample_trace_id": "4175447395282887089"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 19
• 최초 발생: 2026-06-25 00:06 KST
• 최근 발생: 2026-06-25 09:21 KST

Root Cause Summary#

Api::V1::PanosController#index는 (1) ::Pano.search 로 Elasticsearch 쿼리를 실행한 뒤, (2) 결과 record에 대해 MySQL 쪽에서 PanoRepository.default_joins (8개의 INNER/LEFT JOIN + storage preload)와 PanoRepository.permission_joins (review/capture/record/facility/workspace/team × user/group/system_group 조합으로 약 15개의 LEFT JOIN subquery)를 적용한다. 정상 부하에서는 수백 ms 안에 끝나지만, 클러스터 시간대에는 동일 us-west-2 ES 클러스터에서 Pano/Record/Capture _update_document 폴백 경로(Searchable#_update_document — @__changed_model_attributes가 비어 있을 때 전체 문서를 reindex)가 폭주하며 ES query latency가 ~7배 증가했고, 그 결과 같은 ES 색인을 읽는 search index endpoint가 31s 평균, 93s 최대까지 지연되었다. 즉, root cause는 Pano 인덱스 endpoint 자체 코드가 아니라 같은 ES 색인에 대한 동시 write 폴백 폭증으로 인한 ES read 지연이다. permission_joins의 비용은 baseline 부하를 높여 지연을 증폭시킨 기여 요인(contributing factor)이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/panos_controller.rb:16 — def index
• ES 검색 호출: app/repositories/pano_repository.rb:622 — ::Pano.search(...).paginate(...)
• MySQL permission/default joins: app/repositories/pano_repository.rb:76 (default_joins) + app/repositories/pano_repository.rb:116 (permission_joins)
• Failure (slowness) point: ES read 지연 + permission_joins의 15+ LEFT JOIN subquery 평가 시간 누적

def index
  pano_query_option = Cupix::QueryOption::Pano.new(get_query_option(enable_current_team: false), params)
  panos = repository_instance.search(pano_query_option)

  render_api Renderable.new({
    search_result: panos,
    is_collection: true,
    serializer_option: @serializer_option.merge!({
      params: params.permit(:revision_type, :include_download_url).to_h
    })
  })
end

response = ::Pano.search(
  self.query_option.serializable_hash.merge({
    track_total_hits: true
  })
).paginate(
  per_page: self.query_option.per_page,
  page: self.query_option.page
)

BaseRepository#search 는 ES 결과에 대해 다시 MySQL permission_joins 를 적용한다:

def search(query_option = nil)
  _search(query_option)

  begin
    if self.review.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review.id, skip_join: _skip_join?)
    elsif self.review_id.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, review_id: self.review_id, skip_join: _skip_join?)
    elsif self.capture.present?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, capture_id: self.capture.id, skip_join: _skip_join?)
    else
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end

permission_joins는 review/capture/record/facility/workspace/team accessor × User/Group/SystemGroup 조합으로 15개 가까운 LEFT JOIN subquery를 붙인다 (app/repositories/pano_repository.rb:159-301):

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
    WHERE review_permissions.accessor_id = #{sanitized_user_id}
      AND review_permissions.accessor_type = 'User'
      AND review_permissions.review_id = #{sanitized_review_id}
    ) AS review_user_permissions
      ON review_user_permissions.review_id = #{sanitized_review_id}
  ...
")

Searchable#_update_document — 폴백 경로가 인덱스 폭주의 원인:

def _update_document
  Cupix::Logger.debug('begin - _update_document', class: self.class.name, function: __method__)
  ...
  if (attributes_in_database = __elasticsearch__.instance_variable_get(:@__changed_model_attributes).presence)
    ...
  else
    Cupix::Logger.warn('NotFound - attributes_in_database', class: self.class.name, function: __method__)

    _index_document
  end

기대 동작: _update_document는 변경된 attribute만 partial update로 전송한다. 실제 동작: @__changed_model_attributes가 비어 있는 호출이 다수 발생하면서 매번 전체 문서를 _index_document 로 reindex한다. Pano/Record/Capture가 동시에 폭주하면 ES write throughput이 같은 노드의 read latency를 끌어내린다.

Log Evidence#

ES query latency 메트릭 (Datadog Metrics API):

avg:trace.elasticsearch.query.duration{service:cupixworks-api}

값(초): baseline 0.05~0.10 → 인시던트 피크 0.32~0.37 → 회복기 0.10~0.20. 약 5–7배 증가가 클러스터 first_seen ~ last_seen 구간에 정확히 겹친다.

cupixworks-api 전체 request duration 메트릭:

avg:trace.rack.request.duration{service:cupixworks-api}

값(초): 인시던트 구간에서 0.36 ~ 0.58 까지 상승 (평소 ~0.1s).

폴백 reindex warn 폭증 (검색 쿼리):

service:cupixworks-api status:warn "NotFound - attributes_in_database"

샘플(연속 ~10초 안에 ~40+건이 같은 ES 색인에 몰린 케이스):

{"timestamp":"2026-06-25T00:59:04.514Z","status":"warn","message":"NotFound - attributes_in_database","class":"Pano","function":"_update_document"}
{"timestamp":"2026-06-25T00:59:04.514Z","status":"warn","message":"NotFound - attributes_in_database","class":"Pano","function":"_update_document"}
{"timestamp":"2026-06-25T00:59:04.471Z","status":"warn","message":"NotFound - attributes_in_database","class":"Pano","function":"_update_document"}
{"timestamp":"2026-06-25T00:59:02.469Z","status":"warn","message":"NotFound - attributes_in_database","class":"Pano","function":"_update_document"}
{"timestamp":"2026-06-25T00:58:56.508Z","status":"warn","message":"NotFound - attributes_in_database","class":"Pano","function":"_update_document"}
{"timestamp":"2026-06-25T00:58:52.505Z","status":"warn","message":"NotFound - attributes_in_database","class":"Pano","function":"_update_document"}

ClusterRepository에서도 같은 시기에 ES 타임아웃 발생:

{"timestamp":"2026-06-25 06:54:54","status":"error","message":"Operation timed out after 10002 milliseconds with 0 bytes received","class":"ClusterRepository"}

(10s curl timeout — ES 또는 그 앞단의 외부 호출 지연이 동시 시점에 관측됨. ES 부하와 일관된 증상.)

status-board (bun cli/incident-board.ts for-cluster ...) 결과: svc:cupixworks-api::unknown 스코프에서 본 cluster를 포함해 같은 시간대(2026-06-24 16:45–17:59 UTC = 2026-06-25 01:45–02:59 KST)에 7개 cluster가 묶여 인시던트가 열렸다가 자동 resolve 됨 (2026-06-24-svc-cupixworks-api--unknown-2). 같은 서비스에서 동시다발 지연이 있었음을 확인.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• Searchable#_update_document 폴백 경로 비동기화: app/models/concerns/searchable.rb:107-110 — @__changed_model_attributes 가 비어 있을 때 동기 _index_document (전체 문서 reindex) 를 호출하는 대신 BulkIndexWorker.perform_async(self.class.name, [id], 'index') 로 비동기화하는 방향이 안전하다. 이미 Faraday::TimeoutError 분기(line 112-114)는 동일 패턴으로 비동기 처리하고 있다. 동기 폴백을 비동기 큐로 옮기면 API 요청 경로에서 ES write 폭증이 read latency 를 끌어내리는 양상을 차단할 수 있다.
• 폴백 호출 빈도 가시화: NotFound - attributes_in_database warn 을 그대로 두되 @class 별 분포를 Datadog 대시보드에 노출. 어떤 모델 코드 경로가 @__changed_model_attributes 를 비운 상태로 _update_document 를 호출하는지 좁힐 수 있다.

단기 개선 (1주 이내)#

• Pano(및 Record/Capture) save 흐름에서 @__changed_model_attributes 가 비는 호출 지점 추적: _update_document가 호출되는 시점에 saved_changes가 정말 없는 케이스가 합법적인지(예: touch만 한 경우), 아니면 누군가 update_columns/update_column 로 ActiveRecord 변경 트래킹을 건너뛰면서도 callback을 통해 _update_document를 호출하는 케이스가 있는지 식별. 전자라면 ES 폴백을 skip, 후자라면 호출부 수정.
• PanosController#index permission_joins 비용 완화: app/repositories/pano_repository.rb:159-301 의 15+ LEFT JOIN subquery 를 단일 권한 집계 view/materialized 또는 redis 캐시 기반 user→accessible_record_id 셋으로 치환하는 방향 검토. 이 변경은 단독으로 latency 클러스터를 막지 못하지만 baseline 평균을 낮춰 ES 부하 폭증 시 마진을 확보한다.

장기 개선 (재발 방지)#

• ES read/write 분리: Pano/Record/Capture 색인의 read replica 와 write primary 를 분리해 write 폭증이 read latency 에 직접 영향을 주지 않도록 한다.
• ES write rate-limit/backpressure: 모델 콜백에서 직접 _index_document 동기 호출하는 모든 경로(Searchable 모듈 전체)를 BulkIndexWorker 비동기 경로로 통일.
• APM 기반 endpoint latency SLO 모니터: Api::V1::PanosController#index p95 > 5s 가 3분 이상 지속될 때 알림.

Monitoring#

기존에 status-board 가 latency cluster 를 자동 감지했지만, ES write 폭주는 별도로 가시화해야 재발을 빠르게 인지할 수 있다.

ES query latency 추세 (인시던트 시 5–7배 spike 확인용):

avg:trace.elasticsearch.query.duration{service:cupixworks-api}

cupixworks-api 전체 평균 request duration:

avg:trace.rack.request.duration{service:cupixworks-api}

Pano _update_document 폴백 reindex 발생량 (write 폭주 지표):

service:cupixworks-api status:warn "NotFound - attributes_in_database"

PanosController#index slow trace 카운트 — proof query: 수정 후 0 또는 baseline 으로 수렴해야 함:

service:cupixworks-api "Api::V1::PanosController#index" status:warn

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard
  • Searchable#_update_document 폴백 비동기화는 비교적 표면적이며 기존 BulkIndexWorker 경로를 재사용 가능. 다만 Searchable 은 다수 모델이 include 하므로 회귀 영향 범위 확인이 필요.
  • permission_joins 캐시화는 권한 모델 전체 재설계가 필요하므로 별도 큰 작업.