RCA: GroupsController#remove_users Latency (4809ms)

Overview#

What Happened#

2026-05-27 19:38 UTC에 cupixworks-api 서비스의 Api::V1::Admin::GroupsController#remove_users 엔드포인트가 4809ms의 응답 시간을 기록했다. Team 1124의 assigned_customer_success_managers 그룹에서 사용자를 제거하는 PUT 요청이 정상 완료(HTTP 200)되었으나, per-user 순차 처리로 인해 과도한 지연이 발생했다.

Quick Facts#

Timeline#

1. 2026-05-27T19:38:43Z — UserFactory.update_user_groups! 호출 시작 (user 3581)
2. 2026-05-27T19:38:47Z — User.flush_cached_permission 호출 (user 12721)
3. 2026-05-27T19:38:47Z — Cupix::NotificationService.find_email_recipe 3회 호출 (all null)
4. 2026-05-27T19:38:47Z — 요청 완료 [200] PUT /api/v1/admin/teams/1124/groups/assigned_customer_success_managers/remove_users

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::Admin::GroupsController#remove_users",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 4809,
  "max_ms": 4809,
  "sample_trace_id": "2932626941292051342"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-05-27T19:38:41.996Z
• 최근 발생: 2026-05-27T19:38:41.996Z

Root Cause Summary#

GroupsController#remove_users는 사용자를 그룹에서 제거할 때 users.each { |user| @model.users.destroy(user) } 루프로 순차 처리한다. 각 destroy 호출은 GroupedUser 모델의 after_destroy 콜백을 트리거하여 Elasticsearch reindex (reindex_group, reindex_team)와 권한 캐시 flush를 수행한다. assigned_customer_success_managers 그룹의 경우 reindex_team 콜백도 추가로 실행되며, 모든 작업이 HTTP 요청 내에서 동기적으로 처리되어 사용자 수에 비례한 지연이 발생한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/admin/groups_controller.rb:38
• Business logic: app/repositories/admin/group_repository.rb:35
• Failure point (latency source): app/repositories/admin/group_repository.rb:55-57

컨트롤러는 단순히 repository에 위임한다:

def remove_users
  repository_instance.remove_users(params[:user_ids] || [])

  render_api Renderable.new(
    contents: @model
  )
end

Repository의 remove_users에서 per-user 루프가 지연의 핵심 원인이다:

users.each do |user|
  @model.users.destroy(user)
end

각 destroy 호출 시 GroupedUser 모델의 콜백이 실행된다:

after_create :reindex_group
after_create :reindex_team, if: proc { |grouped_user| grouped_user.group.group_type_code == 'assigned_customer_success_managers' }
after_destroy :reindex_group
after_destroy :reindex_team, if: proc { |grouped_user| grouped_user.group.group_type_code == 'assigned_customer_success_managers' }

reindex_group은 Elasticsearch에 문서를 동기적으로 인덱싱한다:

def reindex_group
  return nil if group.nil?

  group.reload.__elasticsearch__.index_document
end

assigned_customer_success_managers 그룹이므로 reindex_team도 매 사용자 제거마다 실행된다:

def reindex_team
  group.team._index_document
end

추가로 after_commit 콜백이 권한 캐시를 flush한다:

after_commit :flush_cached_permitted_items, on: %i[create destroy]

그룹 제거 후 sandbox accessible group 처리도 동기적으로 수행된다. 이 그룹은 assigned_customer_success_managers이므로 해당 조건에는 미해당이지만, customer_success_managers나 account_managers 그룹에서는 추가 N+1이 발생한다:

def remove_from_sandbox_accessible_group(user_ids = [])
  if %w[customer_success_managers account_managers].include?(@model.group_type_code)
    sandbox_accessors = ::User.where(id: user_ids).eager_load(:grouped_users, :groups).select { |user| UserRepository.new(user).sandbox_accessible? == false }

    sandbox_accessible_group = ::Group.find_by(group_type_code: SANDBOX_ACCESSIBLE_GROUP_TYPE_CODE)

    raise Cupix::Errors::System.new(code: 'SYS10000', reason: "#{SANDBOX_ACCESSIBLE_GROUP_TYPE_CODE} not found") if sandbox_accessible_group.nil?

    sandbox_accessible_group.users.destroy(sandbox_accessors) if sandbox_accessors.present?
  end
end

실행 비용 분석 (per user):

4809ms / ~1000ms per user = 약 4-5명의 사용자가 제거된 것으로 추정되며, 이는 trace 로그에서 확인된 다중 find_email_recipe 호출(3회)과 일치한다.

Log Evidence#

Trace ID 2932626941292051342에서 확인된 7개 로그 항목:

Datadog query: service:cupixworks-api trace_id:2932626941292051342

04:38:43 KST | UserFactory | update_user_groups! | "No custom groups found for user 3581, matt.brown@cupix.com"
04:38:47 KST | User | flush_cached_permission | "Deleting cached_permission on user 12721"
04:38:47 KST | Module | flush_cached_permissions | "Flush cached permissions for User 12721"
04:38:47 KST | Cupix::NotificationService | find_email_recipe | "recipe found: null"
04:38:47 KST | Cupix::NotificationService | find_email_recipe | "recipe found: null"
04:38:47 KST | Cupix::NotificationService | find_email_recipe | "recipe found: null"
04:38:47 KST | - | - | "[200] PUT /api/v1/admin/teams/1124/groups/assigned_customer_success_managers/remove_users"

첫 번째 로그(04:38:43)와 완료 로그(04:38:47) 사이 약 4초의 간격은 per-user 순차 처리가 요청 내에서 실행되었음을 확인한다.

추가로 동일 시간대의 update_user_groups! 검색에서 50건 이상의 반복 호출이 확인되어 동일 패턴의 fan-out이 다른 요청에서도 발생하고 있다:

Datadog query: service:cupixworks-api @function:update_user_groups! (19:35-19:42 UTC window)

Worker 서비스에서는 관련 로그가 없어, 모든 작업이 HTTP 요청 내에서 동기적으로 처리됨을 확인했다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/repositories/admin/group_repository.rb:55-57의 per-user destroy 루프를 bulk delete로 변경
• GroupedUser.where(group: @model, user: users).destroy_all 또는 콜백을 건너뛰고 직접 삭제 후 단일 reindex 수행
• Elasticsearch reindex를 루프 밖에서 한 번만 실행하도록 변경

단기 개선 (1주 이내)#

• reindex_group, reindex_team 콜백을 비동기 worker로 이동 (Sidekiq job)
• flush_cached_permitted_items도 비동기로 처리하여 HTTP 응답 시간에서 분리
• 사용자 수가 많을 경우 batch 처리 적용

장기 개선 (재발 방지)#

• GroupedUser 콜백 구조 리팩토링: 동기 콜백 대신 이벤트 기반 비동기 처리 도입
• Admin 엔드포인트에 대한 APM latency alert 추가 (p95 > 2000ms)
• Bulk operation 표준 패턴 수립: 모든 admin bulk 엔드포인트에서 N+1 콜백 방지 가이드라인

Monitoring#

• APM latency 모니터링: resource_name:Api::V1::Admin::GroupsController#remove_users p95 > 2000ms
• Datadog 쿼리:

service:cupixworks-api resource_name:"Api::V1::Admin::GroupsController#remove_users" @duration:>2000ms env:production

• Elasticsearch reindex 빈도 추적: reindex_group 또는 reindex_team 호출 횟수가 분당 50건 초과 시 alert

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard — 콜백 구조 변경은 테스트 범위가 넓으나, 기존 bulk 패턴 참고 가능