RCA: Api::V1::Admin::PointcloudsController#index latency (avg 10021ms)

Overview#

What Happened#

2026-07-03 06:57 KST 무렵 cupixworks-api (production, us-west-2)에서 Api::V1::Admin::PointcloudsController#index 트레이스가 약 10초 (avg/max 10021ms) 소요된 것이 error-sweeper의 APM latency 클러스터로 잡혔다. HTTP 응답은 200으로 정상 반환되었으나 P99 응답 시간이 정상 대비 수백 배 (평상시 ~25ms) 늘어난 단발성 slow-trace이다. 같은 시간대에 svc:cupixworks-api::unknown 스코프의 서비스 저하 인시던트가 열려 있어 (open) 여러 클러스터가 함께 감지된 상황이다.

Quick Facts#

Affected Teams#

로그에서 확인된 caller는 Retool/2.0 user-agent, team.domain=admin, team.id=1 (내부 admin 팀). Retool 대시보드 사용자만 영향을 받았고, 외부 고객 트래픽에는 영향 없음.

Timeline#

1. 2026-07-03 06:33 KST — 동일 endpoint에서 5.5s slow request (duration 5576.73ms), Retool caller, filter=record.id=7332. 유사한 slow-query 조건 사전 발생.
2. 2026-07-03 06:57 KST — 클러스터 first_seen. APM span 10021ms 관측 (trace 2847624830130116499, us-west-2).
3. 2026-07-03 07:03~07:07 KST — 관련 클러스터 d94a3259 (22:03:00Z), cfc2776c (22:07:53Z)가 같은 svc scope로 붙으며 2026-07-02-svc-cupixworks-api--unknown-1 인시던트가 열림 (still open at time of writing).
4. 2026-07-03 조사 시점 — Datadog logs상 동일 시간 창(21:5721:58Z)에서 admin/pointclouds 요청 로그의 duration 필드는 22ms25ms 수준으로 나타남. 즉 10s slow trace의 request-completion 로그는 발견되지 않음 (아래 Log Evidence 참고).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::Admin::PointcloudsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10021,
  "max_ms": 10021,
  "sample_trace_id": "2847624830130116499"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (단발 slow trace)
• 최초 발생: 2026-07-03 06:57 KST
• 최근 발생: 2026-07-03 06:57 KST

Root Cause Summary#

Api::V1::Admin::PointcloudsController#index는 Retool 대시보드가 filter=record.id=X, per_page=300으로 호출하는 admin 검색 endpoint이다. 이 endpoint는 (1) Elasticsearch Pointcloud.search 결과를 페이지네이션한 뒤, (2) PointcloudRepository.permission_joins에서 pointclouds 테이블에 15개 이상의 LEFT JOIN 서브쿼리 (pointcloud_permissions, review_permissions, record_permissions, facility_permissions, workspace_permissions, team_permissions, group 확장 join 포함)를 붙여 사용자 권한을 계산한다. 정상 시 응답은 2030ms이지만, 이 무거운 permission-join SQL이 (a) MySQL side에서 plan degradation을 겪거나 (b) 동시에 열린 다른 slow query와 lock/connection contention을 겪는 경우 10초 규모로 튄다. 클러스터 파일에는 status 200으로 기록되어 있어 요청은 최종 성공했고, 같은 시간대 다른 request 로그의 db 필드가 정상(26ms)임을 감안하면 이 특정 trace만 MySQL replica의 일시적 slow 조건에 걸린 것으로 보인다. 코드 자체의 신규 버그는 아니며, 동일 svc scope에서 최근 7일간 반복적으로 열려 온 cupixworks-api::unknown 서비스 저하 패턴의 한 사례이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/admin/pointclouds_controller.rb:8
• ES search: app/repositories/admin/pointcloud_repository.rb:95-100 → Pointcloud.search(...)
• Permission join (MySQL): app/repositories/admin/pointcloud_repository.rb:112 → 클래스 메서드가 최상위 PointcloudRepository.permission_joins에 위임
• Failure point (latency origin): app/repositories/pointcloud_repository.rb:40-77 및 이후 join 블록 — 15개 이상의 LEFT JOIN 서브쿼리

Controller는 repository_instance.search 한 번만 호출한다:

def index
  pointclouds = repository_instance.search(
    Cupix::QueryOption::Pointcloud.new(get_query_option(enable_current_team: false), params)
  )

  render_api Renderable.new(
    search_result: pointclouds,
    is_collection: true,
    serializer_option: @serializer_option.merge(params: { current_user: current_user })
  )
end

BaseRepository#search는 ES 결과에 대해 permission_joins로 MySQL join을 붙인다:

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?)
    ...
    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

Admin 검색은 ES에 대해 editing_state range(editing_done_at >= now-2w), kind != 'sub' 조건과 group_code 기반 team-id terms 필터가 추가된다:

self.query_option.query[:bool][:should] += [
  {
    terms: {
      editing_state: %w[waiting ready holding editing in_review stopped re_ready]
    }
  },
  {
    range: {
      editing_done_at: {
        gte: 'now-2w'
      }
    }
  }
]

self.query_option.query[:bool][:must_not] << {
  term: {
    kind: 'sub'
  }
}

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

Permission-join SQL은 사용자당 pointcloud/review/record/facility/workspace/team 5개 도메인 × (user/group/system_group) subquery를 LEFT JOIN하고, 최종 MAX(GREATEST(...))로 applied_permission을 산출한다:

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  ...
  _select = "pointclouds.*,
    MAX(pointcloud_user_permissions.permission) AS pointcloud_user_permission,
    MAX(review_user_permissions.permission) AS review_user_permission,
    ...
    MAX(GREATEST(
      IFNULL(pointcloud_user_permissions.permission, 0),
      IFNULL(record_user_permissions.permission, 0),
      ...
      IFNULL(review_public_permissions.permission, 0)
    )) AS applied_permission"

15+ LEFT JOIN 서브쿼리 예시:

record.joins("
  LEFT JOIN (
    SELECT pointcloud_id, permission
    FROM pointcloud_permissions
    WHERE pointcloud_permissions.accessor_id = #{sanitized_user_id}
      AND pointcloud_permissions.accessor_type = 'User'
    ) AS pointcloud_user_permissions
      ON pointcloud_user_permissions.pointcloud_id = pointclouds.id

  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}
  ...
")

기대 동작: ES 조회 후 permission-join query가 지수 시간이 아니므로 20~50ms에 완료되어야 한다. 실제 동작: 이 특정 trace에서만 10021ms — MySQL 측 slow 조건 (plan drift, replica lag, IO contention, 또는 permission 테이블 lock)이 아니면 코드 경로만으로 이 시간이 나오지 않는다.

Log Evidence#

Datadog query (동일 시간대, 동일 endpoint):

service:cupixworks-api "Api::V1::Admin::PointcloudsController#index"
from: 2026-07-02T21:50:00Z
to:   2026-07-02T22:10:00Z

동일 시간대 요청 로그는 duration 20~30ms 수준으로 정상:

{
  "@timestamp": "2026-07-02T21:57:39.698Z",
  "message": "[200] GET /api/v1/admin/pointclouds (Api::V1::Admin::PointcloudsController#index)",
  "duration": 22.35,
  "db": 2.14,
  "view": 0.09,
  "controller": "Api::V1::Admin::PointcloudsController",
  "action": "index",
  "user_agent": "Retool/2.0 (+https://docs.tryretool.com/docs/apis)",
  "team": { "domain": "admin", "id": 1 },
  "params": {
    "filter": "record.id=7358",
    "per_page": "300",
    "fields": ["id","state","published_at","points_count","kind","record","editing_state","error_code","level"]
  },
  "http": { "status_code": 200 }
}

동일 시간창에서 @duration:>3000으로 필터하면 slow trace의 request-completion 로그는 나오지 않는다 (0 hits). 즉 APM에서 잡힌 10s trace는 request-log emitter에 도달하기 전 완료된 것이 아니라, 근처 시간대의 다른 slow request (24분 앞선 5.5s)와 동일한 패턴을 공유한다:

service:cupixworks-api "admin/pointclouds" @duration:>5000
from: 2026-07-02T21:00:00Z
to:   2026-07-02T22:30:00Z

{
  "@timestamp": "2026-07-02T21:33:02.290Z",
  "message": "[200] GET /api/v1/admin/pointclouds (Api::V1::Admin::PointcloudsController#index)",
  "duration": 5576.73,
  "db": 4.12,
  "view": 0.09,
  "params": {
    "filter": "record.id=7332",
    "per_page": "300",
    "fields": ["id","state","published_at","points_count","kind","record","level","editing_state","error_code"]
  },
  "user_agent": "Retool/2.0 (+https://docs.tryretool.com/docs/apis)",
  "team": { "domain": "admin", "id": 1 }
}

주목: 이 5.5s slow request에서도 db: 4.12 (ms), view: 0.09이다. 즉 duration이 5576ms인데 DB 계측치가 4ms — Rails가 계측하는 SQL time과 실제 request wall-time 사이에 5초 이상 gap이 있다. 이는 (a) MySQL client 대기 (connection pool 소진), (b) middleware/외부 서비스 대기 (auth, cognito), 또는 (c) Ruby GC/GVL 스톨 가능성을 시사한다. 코드 경로상 신규로 무거운 로직이 추가된 곳은 확인되지 않는다.

Status board 컨텍스트:

scope: svc:cupixworks-api::unknown
active: 2026-07-02-svc-cupixworks-api--unknown-1  (open)
cluster_ids: e0e15b40..., d94a3259..., cfc2776c...
recent (last 7d): 7 resolved incidents on the same svc::unknown scope

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 코드 변경 불필요. 단발 slow trace이고 응답은 200 성공. 서비스 저하 스코프에서 반복 발생 중이지만 이 클러스터 자체는 즉시 수정 대상 아님.
• 대신 동일 시간대 slow query를 MySQL/RDS Performance Insights에서 확인해 root cause를 확정한다:
  • Slow-query log에서 pointclouds 테이블 대상 LEFT JOIN 문 검색 (review_public_permissions, record_system_group_permissions 등 서브쿼리 이름이 SQL 문에 그대로 등장하지 않으므로 MAX(GREATEST(IFNULL(pointcloud_user_permissions 패턴으로 검색).
  • 같은 시간대 RDS CPU / Innodb row lock time / replica lag 확인.
• 확인 결과가 나오기 전까지 이 클러스터는 resolution: no_change_needed (또는 파이프라인이 사용하는 skip 값)로 처리.

단기 개선 (1주 이내)#

• APM span 계측 강화: PointcloudRepository.permission_joins 블록을 Datadog::Tracing.trace('permission_joins')로 감싸 실제 join SQL 시간이 db 계측에 포함되도록 한다. 현재 duration - db gap 원인이 SQL인지 앱 wait인지 구분 불가능.
• Rails request log에 sql_time/external_time breakdown 추가: duration과 db만으로는 앱 stall과 SQL slow를 구분할 수 없어 재발 조사가 어렵다.
• cupixworks-api::unknown 인시던트 반복 원인 조사: 지난 7일간 7건 발생. svc:cupixworks-api::unknown 스코프에 묶이는 클러스터들의 공통 pattern (endpoint, DB 여부, 시간대)을 error-sweeper에서 aggregation해 rerun.

장기 개선 (재발 방지)#

• permission_joins refactoring: 15+ LEFT JOIN 서브쿼리 방식은 pointclouds row 수 및 사용자 permission 개수에 따라 실행 계획이 크게 흔들린다. materialized permission table 또는 authorization service 도입을 검토.
• Admin 검색 endpoint pagination policy: Retool이 per_page=300을 반복 호출 중. 실제 필요한 컬럼만 select하도록 field allowlist를 좁히고, permission-join 결과의 캐싱(예: request-scope memoization) 여부 확인.
• Slow API SLO 알람: resource_name 기준 P99 latency > 1s 지속 시 알림. 현재 error-sweeper가 사후 감지에 의존.

Monitoring#

Datadog dashboard timeseries widget용 쿼리 (모두 widget-safe metric syntax):

동일 endpoint의 P99 latency 추이:

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::admin::pointcloudscontroller#index}

Slow request rate (>3s):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::admin::pointcloudscontroller#index,@duration:>3000000000}.as_rate()

MySQL side (해당 DB 인스턴스가 metric으로 노출되어 있다면):

avg:aws.rds.cpuutilization{dbinstanceidentifier:*production*}

avg:mysql.innodb.row_lock_time{service:cupixworks-api}

전체 API error rate 관제:

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

Risk Assessment#

• Risk level: low — 단발 slow trace, 사용자 영향 admin/Retool 한정, 응답 성공.
• 예상 복잡도: trivial for 이 클러스터 (no code change). standard for 반복 원인 조사 (RDS Performance Insights + tracing 계측 보강).