ES /docs

Api::V1::BimsController#index (avg 1257ms, max 1745ms)

RCA: Api::V1::BimsController#index Latency (avg 1257ms, max 1745ms)

Overview#

What Happened#

2026-05-26 09:26~11:19 UTC 동안 cupixworks-api 서비스의 Api::V1::BimsController#index 엔드포인트에서 평균 1257ms, 최대 1745ms의 응답 지연이 발생했다. 총 7건의 slow trace가 감지되었으며, us-west-2와 ap-southeast-2 리전 모두에서 발생했다. HTTP 응답은 모두 200이었으나 사용자 체감 지연이 심각한 수준이다.

Quick Facts#

Field Value
resource_name Api::V1::BimsController#index
top_frame app/repositories/bim_repository.rb:138
env production, us-west-2 / ap-southeast-2

Timeline#

  1. 2026-05-26 09:26:45 UTC — 첫 번째 slow trace 감지 (>500ms)
  2. 2026-05-26 11:19:14 UTC — 마지막 slow trace 감지
  3. 2026-05-27 — RCA 분석 완료

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::BimsController#index",
  "service": "cupixworks-api",
  "occurrences": 7,
  "avg_ms": 1257,
  "max_ms": 1745,
  "sample_trace_id": "5072043243790171577"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 7
  • 최초 발생: 2026-05-26T09:26:45.698Z
  • 최근 발생: 2026-05-26T11:19:14.058Z

Root Cause Summary#

BimsController#index는 Elasticsearch 검색 후 MySQL에서 11개의 LEFT JOIN 서브쿼리를 사용한 permission 체크를 수행한다. 이 permission JOIN은 review, facility, workspace, team 레벨의 user/group/system_group 권한을 모두 단일 SQL로 계산하며, GROUP BY id와 MAX(GREATEST(...)) 연산까지 포함된 극도로 복잡한 쿼리이다. Datadog trace에서 DB 시간은 5~30ms로 보고되지만, 실제 총 응답시간의 80% 이상이 "설명되지 않는 시간"으로 나타나는데, 이는 Rails의 DB 시간 측정이 쿼리 실행만 계산하고 connection pool 대기 시간, Ruby GVL 경합, Redis 캐시 lookup (serializer에서 레코드당 5+건)을 포함하지 않기 때문이다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/bims_controller.rb:37
  • Elasticsearch 검색: app/repositories/bim_repository.rb:356 (_search 메서드)
  • Permission JOIN 실행: app/repositories/base_repository.rb:75 → bim_repository.rb:138
  • Serialization + Redis lookups: BimSerializer → ApplicationRecord 캐시 계층

1단계: Controller index action

app/controllers/api/v1/bims_controller.rb:37-46ruby
def index
  bim_query_option = Cupix::QueryOption::Bim.new(get_query_option, params)
  bims = repository_instance.search(bim_query_option)

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

repository_instance.search가 전체 지연의 대부분을 차지한다.

2단계: Base repository search — Elasticsearch → MySQL 2단계 조회

app/repositories/base_repository.rb:70-112ruby
def search(query_option = nil)
  _search(query_option)  # Step 1: Elasticsearch query

  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?)
    else
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end
  # ...
  end
end

Elasticsearch에서 ID를 가져온 후, MySQL에서 해당 레코드에 11개 permission LEFT JOIN을 적용한다.

3단계: 11-way Permission JOIN (핵심 병목)

app/repositories/bim_repository.rb:138-314ruby
def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  _select = "bims.*,
    MAX(review_user_permissions.permission) AS review_user_permission,
    MAX(review_group_permissions.permission) AS review_group_permission,
    MAX(review_public_permissions.permission) AS review_public_permission,
    MAX(facility_user_permissions.permission) AS facility_user_permission,
    MAX(facility_group_permissions.permission) AS facility_group_permission,
    MAX(facility_system_group_permissions.permission) AS facility_system_group_permission,
    MAX(workspace_user_permissions.permission) AS workspace_user_permission,
    MAX(workspace_group_permissions.permission) AS workspace_group_permission,
    MAX(team_user_permissions.permission) AS team_user_permission,
    MAX(team_group_permissions.permission) AS team_group_permission,
    MAX(team_system_group_permissions.permission) AS team_system_group_permission,
    MAX(GREATEST(
      IFNULL(facility_user_permissions.permission, 0),
      IFNULL(facility_group_permissions.permission, 0),
      ...
    )) AS applied_permission"

  record.joins("
    LEFT JOIN (...) AS review_public_permissions ...
    LEFT JOIN (...) AS review_user_permissions ...
    LEFT JOIN (...) AS review_group_permissions ...
    LEFT JOIN (...) AS facility_user_permissions ...
    LEFT JOIN (...) AS facility_group_permissions ...
    LEFT JOIN (...) AS facility_system_group_permissions ...
    LEFT JOIN (...) AS workspace_user_permissions ...
    LEFT JOIN (...) AS workspace_group_permissions ...
    LEFT JOIN (...) AS team_user_permissions ...
    LEFT JOIN (...) AS team_group_permissions ...
    LEFT JOIN (...) AS team_system_group_permissions ...
  ").group('id').select(_select).where("GREATEST(...) > 1")
end

각 서브쿼리가 grouped_users 테이블과 JOIN하며, 최종적으로 GROUP BY id와 GREATEST/IFNULL 체인을 사용한다.

4단계: readable_facility_ids (facility_key 없는 경우)

app/repositories/bim_repository.rb:395-407ruby
self.query_option.query[:bool][:must] += [
  {
    bool: {
      should: [
        {
          terms: {
            "facility.id": self.current_user.readable_facility_ids
          }
        }
      ]
    }
  }
]

facility_key 파라미터가 없으면 current_user.readable_facility_ids를 호출하여 사용자가 읽을 수 있는 모든 facility ID를 조회한다. Redis 캐시 미스 시 추가 DB 쿼리가 발생한다.

Log Evidence#

Datadog에서 사용한 쿼리:

text
service:cupixworks-api "BimsController#index" @duration:>500

핵심 패턴 — 느린 요청에서 DB 시간 대비 total duration 불일치:

text
| Request     | Total Duration | DB Time | Serialization | Unexplained Gap |
|-------------|---------------|---------|---------------|-----------------|
| v2j5kt      | 1742ms        | 11ms    | 50ms          | 1682ms          |
| tyqwx1      | 1526ms        | 18ms    | 28ms          | 1480ms          |
| 9huh28      | 1385ms        | 18ms    | 8ms           | 1358ms          |
| 28jkmi      | 1037ms        | 5ms     | 0ms           | 1031ms          |
| 85cyb0      | 1003ms        | 7ms     | 4ms           | 992ms           |

DB 시간(530ms)과 serialization 시간(050ms)을 합쳐도 총 응답 시간의 5% 미만이다. 나머지 95%가 Rails instrumentation 외부에서 소비된다.

추가 검색 (결과 없음):

text
service:cupixworks-api ("slow query" OR "timeout" OR "ActiveRecord::QueryCanceled" OR "PG::QueryCanceled")
text
service:cupixworks-api ("N+1" OR "bullet" OR "eager" OR "slow" OR "ActiveRecord")

이 두 쿼리 모두 해당 시간 윈도우에서 결과가 없었으며, 명시적 DB timeout이나 N+1 경고가 로깅되지 않았다.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 Permission JOIN SQL 복잡도 + connection pool 대기 11개 LEFT JOIN, GROUP BY, GREATEST 체인 (bim_repository.rb:138-314). 보고된 DB time(5-30ms)은 쿼리 실행만 계산, pool wait 미포함 명시적 slow query 로그 없음 Confirmed
H2 Serializer Redis N+1 (레코드당 5+ cache lookup) ApplicationRecord에서 belongs_to 마다 fetch_cache 호출, 30건 페이지 → 150+ Redis RTT 일부 느린 요청에서 serialization 시간이 0ms로 보고됨 (계측 누락 가능성) Confirmed
H3 Elasticsearch 쿼리 지연 2단계 조회 아키텍처 (ES → MySQL) ES 자체 에러/timeout 로그 없음, DB time에 포함되지 않는 별도 구간 Contributing
H4 Ruby GVL 경합 / GC pause 여러 호스트에서 동시 발생, "unexplained" 시간 패턴 GC 로그나 thread contention 메트릭 직접 확인 불가 Inconclusive
H5 특정 데이터 패턴 (대량 결과) facility 10ofni에서 serialization 600-800ms 관측 대부분의 느린 요청은 per_page: 30, total_entries: 1로 소량 데이터 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • app/repositories/bim_repository.rb:138-314 — permission_joins 메서드에 SQL EXPLAIN 분석 추가하여 실제 실행 계획 확인
  • Connection pool 설정 확인 (database.yml의 pool 크기, checkout_timeout) — pool 대기가 instrumentation에 미포함되므로 로깅 추가 필요
  • ActiveSupport::Notifications를 사용하여 sql.active_record 이벤트에서 connection checkout 시간을 별도로 측정

단기 개선 (1주 이내)#

  • Permission 캐싱: applied_permission 값을 Redis에 캐싱하여 매 요청마다 11-way JOIN을 실행하지 않도록 변경. 키는 user_id:resource_type:resource_id 조합 사용
  • Serializer Redis batch: 레코드당 개별 Redis GET 대신 MGET으로 일괄 조회하여 round-trip 횟수를 150+ → 5~6건으로 감소
  • readable_facility_ids 결과의 Redis TTL 확인 및 적정 캐시 시간 보장

장기 개선 (재발 방지)#

  • Permission 체계를 단일 materialized 테이블로 리팩토링 (user_id, resource_type, resource_id, permission 컬럼). 현재 11개 permission 테이블을 런타임 JOIN하는 방식은 확장성 한계
  • Elasticsearch 검색 결과에 permission 정보를 인덱싱하여 MySQL round-trip 제거 (ES에서 바로 필터링)
  • APM custom span 추가: permission_joins, readable_facility_ids, serializer_cache_lookup 구간을 별도 span으로 측정

Monitoring#

  • Permission JOIN 소요 시간 custom metric 추가:
text
avg:trace.custom.permission_joins.duration{service:cupixworks-api,resource_name:Api::V1::BimsController#index}
  • Connection pool checkout 시간 모니터링:
text
avg:rails.activerecord.pool.checkout_duration{service:cupixworks-api} by {host}
  • BimsController p95 latency 알림 설정 (threshold: 800ms):
text
avg(last_5m):p95:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::BimsController#index} > 0.8

Risk Assessment#

  • Risk level: medium
  • 예상 복잡도: standard — permission 캐싱 도입은 invalidation 전략 설계가 필요하나, 기존 Redis 인프라 활용 가능