RCA: Api::V1::ElementTracesController#index (avg 16164ms, max 18888ms)

Overview#

What Happened#

2026-07-01 11:37–11:49 KST 사이에 cupixworks-api의 Api::V1::ElementTracesController#index 엔드포인트에서 두 건의 극단적인 응답 지연이 발생했다 (avg 16.1s, max 18.9s). 통상적으로 이 엔드포인트의 p-max는 최근 24시간 기준 1~3초 수준이며 12.7초가 관측되던 tail이 이번에 18.9초까지 벌어졌다. 같은 시간대에 동일 컨트롤러의 #bulk (PUT) 요청이 분당 30건 이상 지속적으로 유입되고 있었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-01 11:37 KST — 첫 번째 slow #index 요청 (trace_id 1335364666684600316)
2. 2026-07-01 11:37~11:49 KST — 같은 컨트롤러의 #bulk PUT 요청이 분당 30건 이상 지속 (Datadog Api::V1::ElementTracesController#bulk 검색 로그)
3. 2026-07-01 11:49 KST — 두 번째 slow #index 요청 (trace_id 700053819678212253), max 18888ms 기록
4. 2026-07-01 11:49 KST 이후 — 지연 스파이크 자연 해소, 이후 신규 slow 이벤트 없음

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ElementTracesController#index",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 16164,
  "max_ms": 18888,
  "sample_trace_id": "1335364666684600316"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-07-01 11:37 KST
• 최근 발생: 2026-07-01 11:49 KST

Root Cause Summary#

Api::V1::ElementTracesController#index는 Elasticsearch 검색 결과를 그대로 반환하지 않고, BaseRepository#search 안에서 hit된 ID들에 대해 8개의 LEFT JOIN 서브쿼리를 포함한 permission_joins SQL을 다시 실행한 뒤 (app/repositories/element_trace_repository.rb:40-163) default_joins로 :element, :task, :sitetrack을 eager-load하고 (element_trace_repository.rb:36-38), 마지막으로 serializer에서 element_eager_load: true일 때 nested bim, level, category 필드까지 채워 넣는다 (app/serializers/element_trace_serializer.rb:25-47). 이 구조는 hit 수와 permission 테이블 fanout에 따라 latency가 super-linear로 증가한다. 이번 window에서는 동일 컨트롤러의 #bulk (PUT) 요청이 분당 30건 이상 지속되면서 element_traces 및 관련 permission 테이블에 대한 쓰기·재인덱싱 부하가 컸고, 이로 인해 permission_joins의 SQL·Elasticsearch 인덱스 접근이 tail에서 15~19초까지 벌어진 tail-latency 스파이크로 관측됐다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/element_traces_controller.rb:11-20

def index
  element_trace_query_option = Cupix::QueryOption::ElementTrace.new(get_query_option, params)
  element_traces = repository_instance.search(element_trace_query_option)

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

Search orchestration: app/repositories/base_repository.rb:70-112

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?)
    # ... (review_id / capture branches)
    else
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end
  rescue Elasticsearch::Transport::Transport::Errors::BadRequest => e
    # ...
  rescue Elasticsearch::Transport::Transport::ServerError => e
    raise unless e.message.start_with?('[429]')
    Cupix::Logger.error("Elasticsearch circuit breaker: #{e.message}", ...)

• Step 1: _search executes ES query with track_total_hits: true and paginates (app/repositories/element_trace_repository.rb:301-308).
• Step 2: default_joins eager-loads :element, :task, :sitetrack on the returned ActiveRecord relation (element_trace_repository.rb:36-38).
• Step 3: permission_joins builds an ad-hoc SQL string with eight LEFT JOIN subqueries against facility_permissions, workspace_permissions, team_permissions (user + group + system-group variants) and a GREATEST(...) WHERE clause (element_trace_repository.rb:70-162).

Heavy fanout SQL:

record.joins("
  LEFT JOIN (
    SELECT facility_id, permission
    FROM facility_permissions
    WHERE facility_permissions.accessor_id = #{sanitized_user_id}
      AND facility_permissions.accessor_type = 'User'
    ) AS facility_user_permissions
      ON facility_user_permissions.facility_id = element_traces.facility_id

  LEFT JOIN (
    SELECT facility_id, permission
    FROM facility_permissions
      LEFT JOIN grouped_users
        ON grouped_users.group_id = facility_permissions.accessor_id
        AND grouped_users.user_id = #{sanitized_user_id}
    WHERE facility_permissions.accessor_type = 'Group'
      AND grouped_users.user_id = #{sanitized_user_id}
    ) AS facility_group_permissions
      ON facility_group_permissions.facility_id = element_traces.facility_id
  # ... 6 more LEFT JOIN subqueries: facility_system_group, workspace_user, workspace_group,
  #     team_user, team_group, team_system_group
").group('element_traces.id').select(_select).where(...)

• Failure point (tail-latency amplifier): app/repositories/element_trace_repository.rb:70-162. GROUP BY element_traces.id + MAX(...) + GREATEST(...)는 hit 30개(=default per_page)에 대해 permission 테이블 fanout에 비례해 임시 테이블/sort 스캔을 만든다. 여기에 default_joins의 :element, :task, :sitetrack includes가 걸려 결과 hydration 시 다시 join된다.

Serializer가 nested associations를 추가로 열어봄:

attribute :element do |element_trace, params|
  if params[:element_eager_load]
    element = element_trace.element
    {
      id: element_trace.element_id,
      name: element.name,
      bim: element._bim,
      level: element._level,
      category: element._category,
      # ...
    }
  else
    element_trace._element
  end
end

• Controller가 element_eager_load: true를 항상 세팅함 (element_traces_controller.rb:61-70), 즉 _bim, _level, _category가 record마다 호출된다. default_joins는 :element만 preload하므로 _bim/_level/_category는 record별로 추가 lookup을 유발할 수 있다 (실측 필요).

기대 동작 vs 실제 동작

• 기대: #index 응답이 1~3초 이내 (Datadog max:trace.rack.request.duration 최근 24h baseline).
• 실제: 동일 endpoint tail이 18.9s. 24h 최대는 12.7s인데 이번 window에서 새 tail을 갱신.

Log Evidence#

Datadog query 1 — 컨트롤러 요청 로그 (window 내 #index / #bulk 동시 유입 확인용):

service:cupixworks-api "ElementTracesController#index"
time: 2026-07-01T02:30:00Z ~ 2026-07-01T02:55:00Z

Result: 50건 이상의 [200] GET /api/v1/element_traces (Api::V1::ElementTracesController#index) 로그. 로그에는 duration이 포함되지 않으며 개별 trace_id도 응답 로그에 노출되지 않아 개별 slow 요청을 로그로 특정하는 것은 불가능 (rails 요청 로그 스키마 한계). trace 자체는 APM 스팬 데이터에만 존재.

Datadog query 2 — 동일 window에서 #bulk 부하 확인:

service:cupixworks-api "ElementTracesController"
time: 2026-07-01T02:30:00Z ~ 2026-07-01T02:55:00Z

Sample (11:49~11:54 KST, 즉 last_seen 직후):

2026-07-01 11:54:56 info [200] PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk)
2026-07-01 11:54:53 info [200] PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk)
2026-07-01 11:54:53 info [200] PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk)
2026-07-01 11:54:52 info [200] PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk)
...  (5초 사이 8건 이상)

#bulk는 element_traces 및 연관 permission-관련 테이블을 대량 update + ES reindex하므로 동일 시간대의 #index (read-heavy, join-heavy) 응답이 lock 경합·ES refresh backlog에 노출된다.

Datadog metric 3 — 24h #index max duration baseline:

max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::elementtracescontroller_index}
range: 24h

관측된 상위 값들 (초): 12.77, 8.67, 7.58, 7.16, 6.66, 5.97, 5.96, 5.64, 5.50, 4.96, 4.74, ...

이번 cluster의 18.9s는 24h 최대(12.77s) 대비 +48% tail 갱신이며 avg 16.1s 역시 그 어떤 개별 데이터포인트보다도 높다.

Datadog query 4 — window 내 error/warn 로그:

service:cupixworks-api status:(error OR warn)
time: 2026-07-01T02:30:00Z ~ 2026-07-01T02:55:00Z

결과: 20건. 모두 NotFound - attributes_in_database (Pano/Record/Pointcloud _update_document) — 이 클러스터와 무관한 재인덱싱 warning. ElementTrace 관련 error/warn 없음. Elasticsearch 429 circuit-breaker (SYS20000) 로그도 없음.

Status board 확인:

bun run cli/incident-board.ts for-cluster 85822c16-...
scope: svc:cupixworks-api::unknown
active: null
recent: 최근 7일 내 cupixworks-api service degraded 인시던트 다수 (2026-06-24, 06-25, 06-26 여러 건, 06-27, 06-30, 07-01)

External dependency 인시던트는 없음. 다만 cupixworks-api 자체는 최근 며칠간 반복적으로 degraded 상태로 잡히고 있어 이번 tail-latency도 그 흐름의 일부일 가능성이 있다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

즉시 조치가 필요한 error/장애는 아니다. 2건 슬로우 스팬, 이후 자연 해소, 5xx 없음. Operations action 없음. RCA 결과를 참고자료로 유지하고 아래 개선 방향을 검토.

단기 개선 (1주 이내)#

• Slow query 가시화: app/repositories/element_trace_repository.rb:70-162의 permission_joins SQL이 실제로 몇 ms 걸리는지 span/tag로 노출 (ActiveSupport::Notifications 커스텀 이벤트 또는 Datadog::Tracing.trace('element_trace.permission_joins')). 지금은 span latency는 관측되지만 어느 단계가 tail의 대부분인지 로그·메트릭으로 판단 불가.
• Per-request 로그 강화: Rails 요청 로그에 duration, param_size, record_ids.size, per_page를 추가하여 이런 tail-latency 이벤트 재현 시 원인 파라미터를 즉시 특정할 수 있게 한다.
• 동시 부하 상관관계 확인: #bulk와 #index가 실제로 같은 세션/사용자에서 겹치는지, 아니면 UI가 bulk 저장 직후 index refresh를 유발하는지 확인. 만약 UI 패턴 문제라면 client-side에서 debounce/queue 도입.

장기 개선 (재발 방지)#

• Permission fanout 리팩터: 8개 LEFT JOIN 서브쿼리를 유지하는 대신 (1) 사용자별 accessible facility/workspace/team ID를 애플리케이션 레벨 캐시(예: Redis, per-request memo)로 미리 확보해 element_traces.facility_id IN (...) 형태의 단순 필터로 대체하거나, (2) Elasticsearch 문서에 permission bitmap을 인덱싱해 ES 단에서 필터링을 완결한다. 현재 구조는 hit 수 × permission fanout으로 super-linear.
• Serializer eager-load 검토: element_trace_serializer.rb:25-47의 _bim, _level, _category가 record별 추가 쿼리를 유발하는지 확인하고, 필요 시 default_joins(element_trace_repository.rb:36-38)의 preload에 element: [:bim, :level, :category]를 추가.
• APM tail-latency 알림: #index의 p99 임계치를 5s로 설정한 Datadog monitor 추가 (지금은 12.7s tail이 이미 baseline). 반복 tail이 감지되면 이번 클러스터처럼 자연 해소를 기다리지 않고 조기 대응 가능.

Monitoring#

REQUIRED SUB-SKILL: writing-datadog-monitoring-queries — 아래 쿼리는 모두 timeseries widget에 그대로 넣을 수 있는 형태 (monitor-only 문법 미사용).

#index p99 latency (fix 검증용):

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::elementtracescontroller_index}

#index max latency (tail spike 감지):

max:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::elementtracescontroller_index}

#bulk 요청률 (동시 write 부하 관측):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::elementtracescontroller_bulk}.as_rate()

#index 요청률 (부하 상관관계 비교):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::elementtracescontroller_index}.as_rate()

Elasticsearch circuit-breaker warning (SYS20000) 발생 추적:

service:cupixworks-api "SYS20000"

Risk Assessment#

• Risk level: low — 5xx 없음, 사용자 요청은 200으로 응답, 2건의 tail-latency로 impact 제한적. 단, 반복 tail이 며칠째 관측되고 있어 방치 시 사용자 체감 성능 저하로 이어질 가능성 있음.
• 예상 복잡도: standard (즉시 조치 없음). 장기 permission fanout 리팩터는 별건 프로젝트급.