PointcloudsController#index tail latency — Puma worker thread saturation

RCA: Api::V1::PointcloudsController#index Latency

Overview#

What Happened#

2026-05-26 03:21~13:18 UTC 동안 cupixworks-api 서비스의 Api::V1::PointcloudsController#index 엔드포인트에서 평균 1071ms, 최대 1283ms의 응답 지연이 61건 발생했다. eu-central-1, us-west-2, ap-southeast-2 전 리전에서 관측되었으며, HTTP 에러(4xx/5xx)는 없고 순수 latency 이슈다.

Quick Facts#

Field	Value
resource_name	`Api::V1::PointcloudsController#index`
top_frame	`app/repositories/pointcloud_repository.rb:40`
env	production (eu-central-1, us-west-2, ap-southeast-2)

Affected Teams#

Team / Domain	Error Count	Impact
pclconstruction	16	Pointcloud 목록 로딩 지연
fgip-pkg1	13	Pointcloud 목록 로딩 지연
기타 팀	32	동일 증상

Timeline#

2026-05-26 03:21 UTC — 최초 slow trace 감지 (1071ms avg)
2026-05-26 13:18 UTC — 마지막 slow trace 관측
2026-05-27 — RCA 분석 완료

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::PointcloudsController#index",
  "service": "cupixworks-api",
  "occurrences": 23,
  "avg_ms": 1089,
  "max_ms": 1283,
  "sample_trace_id": "2562514639914176965"
}

Impact#

Service: cupixworks-api
발생 횟수: 61
최초 발생: 2026-05-26T03:21:39.766Z
최근 발생: 2026-05-26T13:18:12.713Z

Root Cause Summary#

PointcloudsController#index 요청의 tail latency(p95: 793ms, p99: 1072ms)는 Puma worker thread 포화로 인한 request queuing이 주 원인이다. Datadog 분석 결과 DB 시간은 평균 109ms(13.6%), serialization은 50ms(6.2%)이며, 전체 응답 시간의 80.2%(avg 642ms)가 "OTHER"로 분류되어 request queue에서 대기한 시간임이 확인되었다. cupix-agent의 check_uploading 고빈도 polling이 worker thread를 점유하여 동일 호스트의 다른 요청(index 포함)이 대기하는 구조적 문제다. 특히 us-west-2의 단일 호스트(ip-10-1-19-190)가 10초간 50개 요청을 처리하며 최대 1992ms 응답을 기록했다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/pointclouds_controller.rb:17
Repository search: app/repositories/pointcloud_repository.rb:315 (Elasticsearch → DB load)
Permission joins: app/repositories/pointcloud_repository.rb:40 (15+ LEFT JOINs)
Serialization: app/serializers/pointcloud_serializer.rb (18+ concern modules)
Render: app/controllers/concerns/renderable_controller.rb:40

app/controllers/api/v1/pointclouds_controller.rb:17-26ruby

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

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

app/repositories/pointcloud_repository.rb:40-70ruby

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  if select.present?
    _select = ApplicationRecord.sanitize_sql(select)
  else
    _select = "pointclouds.*,
    MAX(pointcloud_user_permissions.permission) AS pointcloud_user_permission,
    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(record_user_permissions.permission) AS record_user_permission,
    MAX(record_group_permissions.permission) AS record_group_permission,
    MAX(record_system_group_permissions.permission) AS record_system_group_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(...)) AS applied_permission"
  end
end

app/models/application_record.rb:84-94ruby

def self.belongs_to(name, scope = nil, **options)
  super

  define_method "_#{name}" do |*args, **kwargs, &block|
    if options[:polymorphic]
      fetch_cache(send("#{name}_type"), send("#{name}_id")).merge({
        type: send("#{name}_type")
      }) rescue nil
    else
      model_name = options[:class_name] || name
      model_id = options[:foreign_key] || "#{name}_id"
      fetch_cache(model_name.to_s.classify, send(model_id))
    end
  end
end

기대 동작: index 요청은 Elasticsearch 조회 → DB 로드 → permission joins → serialization 순서로 100-200ms 이내 완료되어야 한다.

실제 동작: DB(109ms) + serialization(50ms) = 159ms만 실제 처리 시간이며, 나머지 642-1100ms는 Puma worker thread를 할당받기까지의 대기 시간이다. 이는 동일 호스트에서 check_uploading polling과 PanosController 요청이 worker thread를 점유하기 때문이다.

Log Evidence#

Datadog에서 사용한 쿼리:

text

service:cupixworks-api PointcloudsController#index @duration:>800

text

service:cupixworks-api PointcloudsController#index @duration:>1000

Latency breakdown (Datadog APM metrics에서 확인):

text

p50: 75ms
p75: 107ms
p90: 344ms
p95: 793ms
p99: 1072ms
max: 1305ms

slow 요청 시간 분포:

text

DB time:            avg 109ms (13.6%)
Serialization:      avg  50ms (6.2%)
OTHER (queuing):    avg 642ms (80.2%)

호스트 집중도 (13:11 UTC 기준):

text

Host: ip-10-1-19-190.us-west-2.compute.internal
Requests in 10s: 50
Avg latency: 265ms
Max latency: 1992ms

Cognito cold-cache 영향 확인:

text

service:cupixworks-api "Fetching an user from Cognito"
→ 50 results (각 호출에 ~1s 추가 latency)

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Puma worker thread 포화로 인한 request queuing	"OTHER" 시간이 전체의 80.2% (avg 642ms); 단일 호스트 10초간 50 req 처리; us-west-2 load 편중 (35-50 req/min vs 4-14)	—	Confirmed
H2	복잡한 permission joins (15+ LEFT JOINs)로 인한 DB 병목	permission_joins에 15개 이상 LEFT JOIN 존재; per-request DB 호출 구조	DB time 평균 109ms (13.6%)로 전체 latency의 소수; slow query 로그 0건	Rejected
H3	N+1 쿼리 문제로 serialization 병목	18+ serializer concerns; `_user`, `_team` 등 dynamic method가 개별 fetch_cache 호출	serialization avg 50ms (6.2%)로 미미; cache hit 시 DB 호출 없음	Rejected
H4	Cognito API cold-cache로 인한 외부 호출 지연	"Fetching an user from Cognito" 50건 확인; 각 호출 ~1s	모든 slow trace에 Cognito 호출이 있는 것은 아님; 기여 요인이나 주 원인은 아님	Contributing factor

Fix Recommendation#

즉시 조치 (Critical)#

check_uploading polling rate 제한: cupix-agent가 호출하는 check_uploading 엔드포인트에 rate limiting 또는 polling interval 증가 적용. 현재 고빈도 polling(31/50 slow requests가 check_uploading)이 Puma worker를 점유하여 다른 요청 대기를 유발.
Puma worker 수 증가 또는 thread pool 확대: us-west-2 인스턴스의 Puma 설정에서 worker/thread 수를 현재 부하에 맞게 조정.

단기 개선 (1주 이내)#

Load balancing 개선: us-west-2에 요청이 집중되는 불균형 해소. ALB의 routing 알고리즘을 least-connections로 변경하거나, auto-scaling 임계치를 조정.
Cognito 캐시 전략 강화: cold-cache 시 ~1s 추가되는 Cognito user fetch에 대해 background refresh 또는 더 긴 TTL 적용.

장기 개선 (재발 방지)#

check_uploading을 WebSocket/SSE로 전환: polling 대신 push 기반 알림으로 전환하여 불필요한 요청 수 자체를 감소.
Permission joins 경량화: 현재 15+ LEFT JOINs를 materialized view 또는 pre-computed permission table로 대체하여 per-request DB 부하 감소.
Request queuing 모니터링 강화: Puma의 queue depth metric을 Datadog에 export하여 thread 포화를 조기 감지.

Monitoring#

Puma queue depth 메트릭 추가:

text

avg:puma.queue_depth{service:cupixworks-api} by {host}

Pointcloud index p95 latency 알림:

text

avg:trace.rack.request.duration.by.resource_name{resource_name:api::v1::pointcloudscontroller_index,env:production}.95percentile > 800ms

check_uploading request rate 모니터:

text

sum:trace.rack.request.hits{resource_name:api::v1::pointcloudscontroller_check_uploading} by {host}.as_rate()

Risk Assessment#

Risk level: medium
예상 복잡도: standard (polling rate 조정은 trivial, load balancing/Puma 설정 변경은 인프라 작업 필요)