RCA: Api::V1::TrashesController#index latency (avg 10908ms, max 10908ms)

Overview#

What Happened#

GET /api/v1/trashes 요청이 2026-07-03 05:03 KST 에 약 10.9초 소요되며 latency 임계값을 초과했다. Rails controller 로직 자체는 성공(HTTP 200)했으나, TrashRepository#search 가 사용자 permission cache 를 model 별로 조회하는 과정에서 4개의 permission 캐시 (Team, Workspace, Facility, Record) 가 동시에 miss 되어 각각 permission table full-join 쿼리를 실행했다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-03 05:03:38 KST — trace 125824883500764732, GET /api/v1/trashes 시작 (user 4568)
2. 2026-07-03 05:07:33 KST — Flushing directly_permitted_items on user 4568, model: Team, min_permission: 2 (cache miss)
3. 2026-07-03 05:07:33 KST — Flushing directly_permitted_items on user 4568, model: Workspace, min_permission: 2 (cache miss)
4. 2026-07-03 05:07:33 KST — Flushing directly_permitted_items on user 4568, model: Facility, min_permission: 2 (cache miss)
5. 2026-07-03 05:08:03 KST — Flushing directly_permitted_items on user 4568, model: Record, min_permission: 2 (cache miss, +30s wall-clock 이후)
6. 2026-07-03 05:06:40 KST — [200] GET /api/v1/trashes 응답 완료 (span 기준 10908ms)

(로그 타임스탬프는 개별 캐시 flush 이벤트가 로거로 flush 되는 시각이며 span duration 은 APM 스팬 값 기준이다.)

Error Log#

Datadog Logs

resource_name: Api::V1::TrashesController#index
service: cupixworks-api
occurrences: 1
avg_ms: 10908
max_ms: 10908
sample_trace_id: 125824883500764732

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-03 05:03:38 KST
• 최근 발생: 2026-07-03 05:03:38 KST
• Duration: avg 10.9s / max 10.9s (임계값 500ms 대비 ~22배)

Root Cause Summary#

TrashRepository#search 는 응답을 만들기 위해 current_user.directly_permitted_item_ids 를 서로 다른 4개 model (Team, Workspace, Facility, Record) 에 대해 순차 호출한다. 각 호출은 Rails.cache.fetch 기반의 permission 캐시를 사용하지만, 이 사용자의 4개 캐시 키가 동시에 모두 miss 상태였다. Cache miss 시 fallback 은 directly_permitted_items 로, 이는 permissions 테이블과 target model 을 join 한 뒤 distinct + pluck(:id) 로 전체 permitted id 집합을 계산하는 무거운 SQL 이다. 4번의 순차 SQL round-trip 이 span 10.9s 의 지배적 원인이며, controller 이후 단계인 Elasticsearch multi-index 검색(9개 index) 은 캐시 조회 이후 실행되므로 지연을 더 악화시켰다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/trashes_controller.rb:12 — TrashesController#index
• Delegated to: app/repositories/trash_repository.rb:8 — TrashRepository#search
• Failure (slow) point: app/repositories/trash_repository.rb:13-16 — 4개의 directly_permitted_item_ids 순차 호출
• Cache layer: app/models/concerns/accessible_entities/cache.rb:19-33 — _directly_permitted_item_ids (Rails.cache.fetch)
• Cache miss fallback: app/models/concerns/accessible_entities/directly_permitted_items.rb:5-49 — permission table join

def index
  trashes = repository_instance.search(@query_option)

  render_api Renderable.new(
    search_result: trashes,
    is_collection: true,
    serializer_option: @serializer_option
  )
end

def search(query_option = { visibility: Trash.visibility[:TRASHED], sort: [{ cycle_state_updated_at: 'desc' }] })
  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'current_user is required') if @current_user.blank?

  query_option = QueryOption.new(query_option)

  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)

기대 동작: cache warm 상태면 4번 모두 Redis hit → 수십 ms. 실제 동작: 4번 모두 miss → 각각 permission table full join SQL 실행.

def _directly_permitted_item_ids(model, visibility = Cyclable.visibility[:UNTRASHED], min_permission: 1, max_permission: MAX_PERMISSION)
  Rails.cache.fetch({
    cached_permission: {
      user_id: id,
      model: model.try(:name),
      min_permission: min_permission,
      max_permission: max_permission,
      t: cached_permission_timestamp
    }
  }, expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
    Cupix::Logger.info("Flushing directly_permitted_items on user #{id}, model: #{model}, min_permission: #{min_permission}}", class: self.class.name, function: __method__, module: 'AccessibleEntities::Cache', user: { id: id })

    directly_permitted_items(model, visibility, min_permission: min_permission, max_permission: max_permission).pluck(:id).uniq
  end
end

캐시 키에 cached_permission_timestamp 가 포함된다. 이 timestamp 는 cached_permission:{user_id} 라는 별도 키에 저장되며 이 키가 만료/삭제되면 이 사용자의 모든 model 하위 캐시가 사실상 동시 invalidate 된다 — 이것이 4개 miss 가 한 트레이스에서 함께 발생한 구조적 원인이다.

def cached_permission_timestamp
  return SecureRandom.hex(10) if admin_team?

  Rails.cache.fetch({ cached_permission: { user_id: id } }, expires_in: DEFAULT_PERMISSION_CACHE_EXPIRES_IN) do
    DateTime.now.to_i
  end
end

Miss 발생 시 fallback path 의 실제 SQL:

def directly_permitted_items(model, visibility = Cyclable.visibility[:UNTRASHED], min_permission: 1, max_permission: MAX_PERMISSION)
  permission_table_name = model.repository_class.permission_table_name
  permission_table_class = permission_table_name.classify.constantize
  scope = model.visibility_scope(visibility)
  query = model.joins(:permissions)
  # ...
  query.where(
    id: query.where(
      "#{permission_table_name}.accessor_id": _user_id,
      "#{permission_table_name}.accessor_type": 'User'
    ).where("#{permission_table_name}.permission >= ?", min_permission)
     .where("#{permission_table_name}.permission <= ?", max_permission)
    .or(
      query.where(
        "#{permission_table_name}.accessor_id": _groups,
        "#{permission_table_name}.accessor_type": 'Group'
      ).where("#{permission_table_name}.permission >= ?", min_permission)
       .where("#{permission_table_name}.permission <= ?", max_permission)
    )
  ).distinct.merge(scope)
end

Team/Workspace/Facility/Record 각각에 대해 위 subquery+OR+distinct join 을 실행 → 사용자가 큰 team 소속일수록 각 쿼리 소요 시간이 급증한다.

추가로 latency 를 더하는 요인: cache lookup 완료 후 TrashRepository#search 는 9개 Elasticsearch index (Workspace, Facility, Bim, Level, Record, Capture, Pointcloud, Review, AnnotationLayer) 를 하나의 multi-index search 로 조회한다 (trash_repository.rb:195-200).

또한 directly_permitted_items.rb:53 에는 잠재적 버그가 있다 — visibility = Cyclable.visibility[:UNTRASHED] 는 keyword argument 문법이 아니라 assignment 이므로 caller 가 넘긴 Trash.visibility[:ALL] 인자가 무시되고 항상 UNTRASHED 가 사용된다. 이 자체는 latency 원인은 아니지만, TRASHED 항목을 찾는 컨트롤러에서 UNTRASHED 스코프로 permitted id 를 계산하고 있다는 의미이므로 별도 이슈로 기록할 필요가 있다. (uncertain — 코드 상 명백한 시그니처이나 실제 프로덕션 동작에서의 데이터 오염 여부는 추가 검증 필요)

Log Evidence#

Datadog query (재현):

service:cupixworks-api trace_id:125824883500764732

Trace 내 permission cache flush 로그 (4건 모두 miss):

{"timestamp": "2026-07-03 05:07:33 KST", "status": "info", "class": "User", "function": "_directly_permitted_item_ids", "message": "Flushing directly_permitted_items on user 4568, model: Team, min_permission: 2}"}
{"timestamp": "2026-07-03 05:07:33 KST", "status": "info", "class": "User", "function": "_directly_permitted_item_ids", "message": "Flushing directly_permitted_items on user 4568, model: Workspace, min_permission: 2}"}
{"timestamp": "2026-07-03 05:07:33 KST", "status": "info", "class": "User", "function": "_directly_permitted_item_ids", "message": "Flushing directly_permitted_items on user 4568, model: Facility, min_permission: 2}"}
{"timestamp": "2026-07-03 05:08:03 KST", "status": "info", "class": "User", "function": "_directly_permitted_item_ids", "message": "Flushing directly_permitted_items on user 4568, model: Record, min_permission: 2}"}

Response:

[200] GET /api/v1/trashes (Api::V1::TrashesController#index)

동일 시간대 다른 사용자(1054)에서도 짧은 시간 안에 permission cache miss 가 반복 발생 — 이는 permission cache 가 개별 사용자마다 자주 invalidate 되는 워크로드 패턴을 시사한다:

service:cupixworks-api "Flushing directly_permitted_items"
2026-07-03 05:14:36–05:14:58 KST 사이 user 1054 에 대해 30건 이상 miss 이벤트 관측

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 대상 파일: app/repositories/trash_repository.rb:13-16
• 방향: 4개의 directly_permitted_item_ids 호출을 병렬화 하거나 일괄 조회 API 로 대체. 각 호출은 사용자의 permission 테이블을 독립적으로 join 하므로 병렬 실행 시 wall-clock 을 ~1/4 로 단축 가능. Rails 스레드 안전성/커넥션 풀 크기를 고려해야 하므로 우선은 _readable_workspace_ids / _readable_facility_ids / _readable_record_ids 처럼 이미 존재하는 model-특화 캐시 헬퍼로 대체하는 방향이 안전 (accessible_entities/cache.rb:35-78 참조 — Team 만 없음).
• 대상 파일: app/models/concerns/accessible_entities/cache.rb:19-33
• 방향: _directly_permitted_item_ids 를 batch-fetch (multi_read) 로 개편하여 4개 model 캐시를 1 round-trip 으로 조회. Rails.cache.fetch_multi 사용 시 miss 된 model 만 계산.
• 우선순위: Trash.visibility[:ALL] 파라미터 무시 이슈(directly_permitted_items.rb:53) 는 정확성 문제이므로 별도 이슈로 트래킹 필요.

단기 개선 (1주 이내)#

• Permission 캐시 무효화 정책 재검토: cached_permission_timestamp 하나가 만료되면 해당 사용자의 모든 model 캐시가 동시에 stale 로 간주되어 next request 에서 4개 miss 를 유발하는 구조. TTL 을 사용자 활동성에 따라 다르게 두거나, 백그라운드 warm-up (예: 로그인 직후 pre-computation Sidekiq job) 을 추가.
• Cupix::Logger.info 인자로 넘어가는 model: 는 Class 객체 자체를 문자열 보간해 #<Class:...> 처럼 찍히지는 않지만, model.try(:name) 은 caching key 로만 쓰이고 로그 문자열에는 model 인스턴스를 그대로 넣고 있음 — 로깅 명확성 개선 여지 있음 (nit).
• TrashesController#index 에 slow-query threshold 알림 (>3s) 을 위한 별도 계측 태그 추가.

장기 개선 (재발 방지)#

• Permission id 계산을 read-time 이 아닌 write-time (permission 변경 시 사전 계산) 으로 옮기는 materialized view / summary 테이블 도입 검토. 특히 대형 team 소속 사용자에 대한 응답 시간 결정론화.
• Elasticsearch 검색과 permission id 계산의 pipeline 개선: ES 쿼리에 사용자 permission 을 직접 filter 로 넣기보다 pre-computed readable_*_ids bitmap/roaring set 를 캐시.

Monitoring#

• Metric: Api::V1::TrashesController#index p95/p99 latency 알림 (>3s p95 로 임계값 설정)
• Metric: permission cache miss ratio (Flushing directly_permitted_items 발생률)
• Datadog 쿼리 예시:

APM span 기준 TrashesController latency:

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

Permission cache miss 이벤트 rate (전체):

count:cupixworks-api.log{@message:"Flushing directly_permitted_items"}.as_rate()

500ms 초과 요청 발생률:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::trashescontroller#index,duration:>500ms}.as_rate()

Risk Assessment#

• Risk level: medium — 단일 사용자·단일 발생이지만 재현 조건(4개 permission 캐시 동시 miss)이 timestamp 기반 invalidation 구조상 사용자당 주기적으로 발생 가능하며, 대형 team 소속 사용자에게 반복될 가능성 높음.
• 예상 복잡도: standard — 캐시 batch fetch / model-특화 헬퍼 재사용은 표준 리팩터링. 병렬화는 커넥션 풀 검증 필요.