RCA: Api::V1::TrashesController#index Latency (avg 2323ms, max 2789ms)

Overview#

What Happened#

2026-05-26 04:34~04:50 UTC 사이에 cupixworks-api의 TrashesController#index 엔드포인트가 평균 2323ms, 최대 2789ms의 응답 시간을 기록했다. 총 5건의 요청이 모두 HTTP 200을 반환했지만, 정상 응답 시간(~900ms)의 2.5배를 초과했다. 영향을 받은 사용자는 단일 팀(hec-test-dangjin)의 peter.nam@cupix.com 계정이다.

Quick Facts#

Timeline#

1. 2026-05-26T04:34:35Z — 최초 지연 요청 발생 (2787ms, host: ip-10-1-80-134)
2. 2026-05-26T04:34:46Z — 두 번째 요청 (2294ms, host: ip-10-1-144-228)
3. 2026-05-26T04:46:46Z — 세 번째 요청 (2154ms, host: ip-10-1-80-134)
4. 2026-05-26T04:50:34Z — 마지막 지연 요청 (1916ms, host: ip-10-1-144-228)
5. 2026-05-26T13:25:00Z — 동일 엔드포인트 응답 시간 900ms로 정상화 확인

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::TrashesController#index",
  "service": "cupixworks-api",
  "occurrences": 5,
  "avg_ms": 2323,
  "max_ms": 2789,
  "sample_trace_id": "950733167875203257"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 5
• 최초 발생: 2026-05-26T04:34:35.294Z
• 최근 발생: 2026-05-26T04:50:31.527Z
• 영향 범위: 단일 사용자(peter.nam@cupix.com), 단일 팀(hec-test-dangjin, team_id: 1222). 기능 장애가 아닌 UX 지연(Trash 목록 로딩 2-3초).

Root Cause Summary#

TrashRepository#search가 9개 Elasticsearch 인덱스(Workspace, Facility, Bim, Level, Record, Capture, Pointcloud, Review, AnnotationLayer)에 대해 동시에 복잡한 bool query를 실행하면서 발생하는 구조적 성능 문제이다. Datadog 로그에서 DB time이 일관되게 ~1000ms로 기록되었으나, 이는 4회의 directly_permitted_item_ids SQL 쿼리(권한 ID 조회)에 소요된 시간이다. 나머지 1000-1800ms는 Elasticsearch multi-index 검색에 소요되었으며, 이는 Datadog의 db metric에 포함되지 않는다. 결과가 13건임에도 불구하고 9개 인덱스를 모두 스캔하는 쿼리 구조가 근본 원인이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/trashes_controller.rb:11 — index action
• Permission query: app/repositories/trash_repository.rb:13-16 — 4회의 directly_permitted_item_ids 호출
• ES query build: app/repositories/trash_repository.rb:18-193 — 9개 모델별 bool query 구성
• ES execution: app/repositories/trash_repository.rb:195-200 — multi-index search + pagination
• Serialization: app/serializers/trash_serializer.rb:1-78 — FastJsonapi serializer (ES _source 직접 사용)

1단계: 권한 ID 조회 (~1000ms)

readable_team_ids = @current_user.directly_permitted_item_ids(::Team, Trash.visibility[:ALL], min_permission: 2) & [@current_team.id]
readable_workspace_ids = @current_user.directly_permitted_item_ids(::Workspace, Trash.visibility[:ALL], min_permission: 2)
readable_facility_ids = @current_user.directly_permitted_item_ids(::Facility, Trash.visibility[:ALL], min_permission: 2)
readable_record_ids = @current_user.directly_permitted_item_ids(::Record, Trash.visibility[:ALL], min_permission: 2)

이 4개의 호출은 각각 DB permissions 테이블을 JOIN하여 사용자가 접근 가능한 엔티티 ID를 조회한다. PERMISSION_CACHE_ENABLED가 true인 경우 Rails.cache를 사용하지만, 캐시 키에 visibility 파라미터가 포함되지 않아 캐시 miss 시 전체 visibility scope로 쿼리가 실행된다.

def directly_permitted_item_ids(model, visibility = Cyclable.visibility[:UNTRASHED], min_permission: 1, max_permission: MAX_PERMISSION)
  if PERMISSION_CACHE_ENABLED
    _directly_permitted_item_ids(model, visibility = Cyclable.visibility[:UNTRASHED], min_permission: min_permission, max_permission: max_permission)
  else
    directly_permitted_items(model, visibility, min_permission: min_permission, max_permission: max_permission).pluck(:id).uniq
  end
end

2단계: Elasticsearch multi-index query (~1000-1800ms)

response = Elasticsearch::Model.search(
  query_option.serializable_hash, [::Workspace, ::Facility, ::Bim, ::Level, ::Record, ::Capture, ::Pointcloud, ::Review, ::AnnotationLayer]
).paginate(
  per_page: query_option.per_page,
  page: query_option.page
)

9개 인덱스에 대해 단일 search request를 보내며, 각 인덱스별로 bool query에 should + must + must_not 조건이 조합된 복잡한 쿼리를 실행한다. 결과가 1~3건이더라도 모든 인덱스의 scoring 과정을 거쳐야 하므로 응답 시간이 길어진다.

3단계: Serialization (< 1ms)

attribute :id do |item|
  item['_source']['id']
end

Serializer는 ES _source에서 직접 필드를 추출하므로 추가 DB 쿼리 없이 빠르게 완료된다. Datadog 로그에서 serialization time이 0-1ms로 확인되었다.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api resource_name:"Api::V1::TrashesController#index" env:production @duration:>500ms

5건의 요청 로그에서 추출한 핵심 패턴:

{
  "timestamp": "2026-05-26T04:34:38.263Z",
  "duration_ms": 2787.56,
  "db_ms": 997.39,
  "view_ms": 0.1,
  "serialization_ms": 0,
  "total_entries": 2,
  "user_id": 751,
  "team_id": 1222,
  "host": "ip-10-1-80-134",
  "params": "page=1, per_page=25, fields: has_child, counts_info, parents_info..."
}

{
  "timestamp": "2026-05-26T04:50:34.697Z",
  "duration_ms": 1916.18,
  "db_ms": 1007.20,
  "view_ms": 0.1,
  "serialization_ms": 0,
  "total_entries": 1,
  "user_id": 751,
  "team_id": 1222,
  "host": "ip-10-1-144-228"
}

핵심 관찰:

• DB time은 모든 요청에서 1000ms로 일정 (total_entries 13건과 무관)
• 총 duration에서 DB+view+serialization을 제외한 ~1000-1800ms가 Elasticsearch 쿼리에 소요
• 3개의 서로 다른 app server에서 발생하여 단일 인스턴스 문제 배제
• 동일 세션(125655eaa08ba463d926be0c14ef4b8a354b3202)에서 반복 호출

APM metric 확인:

trace.rack.request.duration (resource: Api::V1::TrashesController#index)
- 04:30 UTC: avg 2.54s
- 04:45 UTC: avg 2.16s
- 04:50 UTC: avg 2.18s
- 13:25 UTC: avg 0.90s (정상화)

오후에 정상화된 것은 permission cache가 warm된 이후 DB query 시간이 단축되었기 때문으로 판단된다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/trash_repository.rb:13-16: 4회의 directly_permitted_item_ids 호출을 병렬화하거나, 이미 캐시된 directly_readable_*_ids 메서드를 활용하여 중복 쿼리를 제거해야 한다. 특히 Trash.visibility[:ALL]로 호출하지만 실제로는 UNTRASHED scope로 실행되는 불일치를 수정해야 한다.

단기 개선 (1주 이내)#

• Elasticsearch query 최적화: 9개 인덱스를 한번에 검색하는 대신, 사용자에게 실제 trash 항목이 있는 인덱스만 선택적으로 검색하는 2-phase 접근을 고려한다. 먼저 각 인덱스의 count를 확인하고, 결과가 있는 인덱스만 full query를 실행한다.
• Permission cache key에 visibility 포함: _directly_permitted_item_ids 캐시 키에 visibility 파라미터를 추가하여 ALL vs UNTRASHED 요청이 올바르게 분리 캐시되도록 한다.

장기 개선 (재발 방지)#

• Trash 목록 전용 denormalized 인덱스를 Elasticsearch에 생성하여 9개 인덱스 동시 검색을 단일 인덱스 검색으로 대체한다.
• Permission ID 조회 결과를 request-scoped 캐시(RequestStore)에 저장하여 동일 요청 내에서 중복 DB 호출을 방지한다.

Monitoring#

• Datadog APM에서 TrashesController#index p95 latency alert 추가 (threshold: 1500ms)

avg(last_5m):trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::trashescontroller#index,env:production} > 1.5

• Elasticsearch slow query 로그를 info 레벨로 활성화하여 multi-index 검색 소요 시간을 가시화한다.

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 기능 장애가 아닌 UX 지연 문제로, 사용자가 Trash 목록을 자주 조회하지 않는 한 비즈니스 영향은 제한적이다. 단, 데이터가 많은 팀에서는 지연이 더 악화될 수 있다.