RCA: Api::V1::FloorplansController#index avg 73981ms, max 147757ms

Overview#

What Happened#

2026-07-11 04:38 KST ~ 05:05 KST 사이 cupixworks-api(us-west-2, tenant cupix) 에서 Api::V1::FloorplansController#index 요청 3건이 평균 73.9초, 최대 147.7초까지 지연되었다. HTTP 상태는 200으로 성공했지만 요청 시간이 정상 대비 수백 배 늘어난 latency 이벤트다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-11 04:38 KST — 첫 slow trace 관측 (first_seen 2026-07-10T19:38:40.382Z)
2. 2026-07-11 04:38 ~ 05:05 KST — 동일 resource 에서 3건의 slow request 발생, 최대 147.7초 기록
3. 2026-07-11 05:05 KST — 마지막 slow trace 관측 (last_seen 2026-07-10T20:05:51.892Z)
4. 2026-07-11 05:29 KST 이후 — Datadog 로그 상 Api::V1::FloorplansController#index 요청이 다시 정상 응답(200)으로 관측됨

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FloorplansController#index",
  "service": "cupixworks-api",
  "occurrences": 3,
  "avg_ms": 73981,
  "max_ms": 147757,
  "sample_trace_id": "4203370989181188790"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 3
• 최초 발생: 2026-07-11 04:38 KST
• 최근 발생: 2026-07-11 05:05 KST
• Region: us-west-2
• Tenant: cupix

Root Cause Summary#

Api::V1::FloorplansController#index 는 FloorplanRepository#search 를 호출하고, search 는 내부적으로 두 단계를 실행한다. 먼저 _search 에서 사용자가 접근 가능한 floorplan id 를 뽑기 위해 FloorplanRepository.permission_joins(::Floorplan, current_user, ...).where(level_id: level_ids).pluck(:id) 를 실행하여 12개의 서브쿼리 LEFT JOIN (review/level/facility/workspace/team + user/group/system_group permission) 을 돌린 뒤 결과 id 배열을 Elasticsearch terms 필터에 그대로 넣는다. 이어 BaseRepository#search 가 ES 응답의 hit 를 다시 동일한 permission_joins 로 hydration 하여 같은 12-way join 을 한 번 더 실행한다. tenant cupix 처럼 facility/level/team 수가 많고 grouped_users 도 큰 워크스페이스에서는 이 두 번의 permission SQL 이 각각 수십 초 이상 걸릴 수 있으며, _search 단계에서는 terms 필터에 넣기 위해 페이지네이션이 적용되지 않은 전체 id 를 pluck 해와 SQL/ES 양쪽에서 latency 가 누적되어 요청 총 시간이 73~147초까지 늘어난 것으로 판단된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/floorplans_controller.rb:17 (FloorplansController#index)
• Repository dispatch: app/repositories/floorplan_repository.rb:307 (permission_joins(...).pluck(:id) — permission SQL 1차 실행)
• 결과 hydration: app/repositories/base_repository.rb:81 (permission_joins(default_joins(response.records), ...) — permission SQL 2차 실행)
• Failure point (latency): app/repositories/floorplan_repository.rb:40-236 — 12개 서브쿼리 LEFT JOIN 을 포함한 permission_joins 정의. 이 SQL 이 두 번 호출되면서 응답이 늘어짐.

Controller 는 옵션을 파싱한 뒤 저장소 search 를 호출한다:

def index
  floorplan_query_option = Cupix::QueryOption::Floorplan.new(get_query_option, params)
  floorplans = repository_instance.search(floorplan_query_option)

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

_search 는 ES 검색 전에 accessible floorplan id 를 뽑기 위해 무거운 permission SQL 을 실행하고, 그 결과를 그대로 ES terms 필터에 밀어 넣는다. 페이지네이션은 이후 paginate(per_page:, page:) 단계에서만 적용되므로 pluck 은 사용자의 전체 접근 가능한 floorplan 을 대상으로 한다:

elsif self.current_user.present?
  accessible_floorplans = FloorplanRepository.permission_joins(::Floorplan, self.current_user, select: 'floorplans.id', review_id: review_id).where(level_id: level_ids)
  self.query_option.query[:bool][:should] << {
    terms: {
      id: accessible_floorplans.pluck(:id)
    }
  }
end

permission_joins 는 review/level/facility/workspace/team 도메인별로 user/group/system_group 권한을 각각 서브쿼리로 만들어 총 12개의 LEFT JOIN 을 붙이고, grouped_users 를 조인하며, GROUP BY floorplans.id 로 집계한다:

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  # ... 12개 LEFT JOIN (review_public/user/group, level_user/group,
  # facility_user/group/system_group, workspace_user/group,
  # team_user/group/system_group) ...
  record.joins("...").group('id').select(_select).where("...")
end

BaseRepository#search 는 _search 결과(ES hit) 를 다시 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 # = self.review_id.nil?
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end

기대 동작: floorplan list 응답이 수백 ms 이내(정상 GET /api/v1/floorplans 는 200 응답, 로그상 즉시 완료). 실제 동작: 동일 사용자/워크스페이스 조합에서 permission SQL 이 두 번 실행되고 pluck(:id) 결과가 커지면서 요청 시간이 73~147 초까지 늘어남.

Log Evidence#

Cluster 파일의 대표 span 요약:

{
  "resource_name": "Api::V1::FloorplansController#index",
  "service": "cupixworks-api",
  "occurrences": 3,
  "avg_ms": 73981,
  "max_ms": 147757,
  "sample_trace_id": "4203370989181188790"
}

Datadog 로그 검색 결과 (service:cupixworks-api "FloorplansController", 2026-07-10T19:00Z ~ 2026-07-10T20:30Z):

• 인시던트 시간대(19:38 ~ 20:05 UTC) 에는 FloorplansController#index 관련 request-completed 로그가 관측되지 않는다 (Datadog 최근 결과는 2026-07-11 05:29 KST 이후에만 존재). 최대 147.7초 요청은 관측 창을 넘겨 로그가 잘렸거나, 클라이언트/proxy timeout 으로 응답 로그가 남지 않은 것으로 추정된다 — uncertain, needs verification via APM trace 4203370989181188790.
• 이후 정상화된 시점의 access 로그는 200 응답으로 즉시 종료됨:

2026-07-11 05:29:59 [200] GET /api/v1/floorplans (Api::V1::FloorplansController#index)
2026-07-11 05:29:59 [200] GET /api/v1/floorplans (Api::V1::FloorplansController#index)
2026-07-11 05:29:47 [200] GET /api/v1/reviews/vte9b8/floorplans (Api::V1::FloorplansController#index)
2026-07-11 05:29:42 [200] GET /api/v1/floorplans (Api::V1::FloorplansController#index)

Datadog 쿼리:

service:cupixworks-api "FloorplansController"
time: 2026-07-10T19:00:00Z ~ 2026-07-10T20:30:00Z

service:cupixworks-api "FloorplanRepository"
time: 2026-07-10T19:00:00Z ~ 2026-07-10T20:30:00Z
→ 0 hits (repository 내부 로그는 Datadog 로 나오지 않음)

service:cupixworks-api status:warn
time: 2026-07-10T19:30:00Z ~ 2026-07-10T20:10:00Z
→ 인시던트와 직접 관련된 exception/timeout 없음

동일 서비스에 대해 status-board 는 svc:cupixworks-api::unknown scope 에서 2026-07-10 하루에만 4건의 "cupixworks-api service degraded" 인시던트가 resolved 상태로 기록되어 있음 (2026-07-10-svc-cupixworks-api--unknown-1..4), API 전반이 반복적으로 흔들리는 시점과 겹친다 — 본 latency 클러스터는 그 지연 스파이크의 일부일 가능성이 있음 (context).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/floorplan_repository.rb:307 의 accessible_floorplans.pluck(:id) 접근을 재검토. 현재는 사용자가 접근 가능한 모든 floorplan id 를 SQL 로 뽑아 ES terms 필터로 넣는 구조라, 접근 권한이 많은 tenant 에서 latency 가 선형 이상으로 증가한다. 아래 두 방향 중 하나가 필요:
  1. 접근 권한 필터를 ES 인덱스 필드(예: accessible_user_ids, permission_scope) 로 옮겨 terms 필터를 SQL 없이 구성하도록 재설계.
  2. 즉시 완화가 필요하다면 pluck(:id) 대신 select(:id) + subquery 로 넘겨 Rails 메모리로 id 를 모두 로드하지 않도록 하되, permission_joins SQL 자체가 여전히 무겁기 때문에 근본 해결은 아님.
• 근본 원인은 permission_joins 가 두 번 실행되는 것이므로, BaseRepository#search(app/repositories/base_repository.rb:70-82) 의 hydration 경로에서 이미 _search 단계에서 얻은 accessible_floorplans 를 재사용하도록 설계 변경 필요.

단기 개선 (1주 이내)#

• permission_joins 및 accessible id 조회 지점에 ActiveSupport::Notifications 또는 Cupix::Logger 로 실행 시간 계측을 추가해 SQL/ES 각각의 latency 를 Datadog 에 로그로 남긴다. 현재 이 클래스의 내부 지연을 관측할 방법이 없어 재발 원인 확인이 어렵다.
• Api::V1::FloorplansController#index 에 대해 resource_name 기준 APM latency 알림(P95 > 5s) 을 추가.
• FloorplanRepository 스펙에 대규모 permission 데이터셋(예: facility/level/team 각 수백 개) 을 fixture 로 만들어 회귀 테스트를 준비.

장기 개선 (재발 방지)#

• floorplan 뿐 아니라 review/facility/workspace 등 다른 도메인 repository 도 동일한 permission_joins 패턴을 공유한다면 (H1 근거의 review/level/facility/workspace/team 도메인 확장 코드), 전사적으로 권한 필터를 SQL 조인이 아닌 denormalized 인덱스(예: material view, ES field, cached permission set) 로 이관하는 계획이 필요.
• BaseRepository#search 가 _search 결과를 다시 permission_joins 로 재검사하는 이중 실행 구조를 리팩터링 대상으로 등록. 두 번의 실행 중 하나(예: hydration 시점) 는 이미 _search 에서 필터링된 결과라는 가정 하에 skip 가능해야 한다.

Monitoring#

Release dashboard 에 아래 timeseries widget 을 추가해 회귀 여부를 관측한다.

Floorplan list P95 latency (초):

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::floorplanscontroller#index}

Floorplan list 요청량 (분당):

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

전체 cupixworks-api P95 latency (컨텍스트):

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

Rails 5xx 에러율 (분당):

sum:trace.rack.request.errors{service:cupixworks-api}.as_rate()

Risk Assessment#

• Risk level: medium — 실사용자에게 200 은 반환됐지만, 최대 147초 지연은 클라이언트/프록시 timeout, 후속 요청 폭주로 이어질 수 있음.
• 예상 복잡도: standard — permission_joins 재사용/캐시화 또는 ES 필드 이관은 명확한 방향이지만, Floorplan 이외 다수 도메인이 동일 패턴을 공유해 리팩터링 범위가 클 수 있음.