Api::V1::UsersController#index (avg 10157ms, max 10157ms)

RCA: Api::V1::UsersController#index latency (avg 10157ms)

Overview#

What Happened#

2026-07-03 12:24 KST에 eu-central-1 리전의 cupixworks-api 서비스에서 Api::V1::UsersController#index 요청 한 건이 10.2초에 완료된 latency trace가 검출되었다. 응답 자체는 HTTP 200이었으며, 에러 로그는 남지 않았다. 동일 endpoint는 정상 처리(수백 ms 이내) 트래픽이 동시간대에 다수 존재해, 특정 요청 하나만 예외적으로 느린 tail-latency 이벤트로 판단된다.

Quick Facts#

Field	Value
resource_name	`Api::V1::UsersController#index`
service	`cupixworks-api`
cluster_type	`latency`
avg_duration_ms	`10157`
max_duration_ms	`10157`
sample_trace_id	`1390565248288342715`
env	production, eu-central-1
tenant	`cupix`

Affected Teams#

Team / Domain	Error Count	Impact
cupixworks-api / User listing (eu-central-1)	1 slow request	요청 한 건이 10초 지연되어 UI가 사용자 목록 로딩 중 체감 지연을 겪었을 가능성. 다른 동시간 요청은 정상.

Timeline#

2026-07-03 12:23:19 KST — eu-central-1에서 OpcOperation이 OPC API access token 획득 실패 (ICS-11388, HTTP 409, Service Instance stopped). Users endpoint와 직접 관계는 없으나 동시간대 upstream 이슈 존재.
2026-07-03 12:24:28 KST — 같은 OPC 409 에러 재발.
2026-07-03 12:24:51 KST — Api::V1::UsersController#index 요청이 10.2초에 응답 완료 (trace_id 1390565248288342715). 응답 코드 200. 이 요청이 이번 cluster의 first/last seen.
2026-07-03 12:24:52 ~ 12:26:56 KST — 같은 endpoint에서 200 응답이 지속적으로 로그됨 (정상 latency). 다른 slow trace는 관측되지 않음.

Error Log#

Datadog Logs

text

{
  "resource_name": "Api::V1::UsersController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 10157,
  "max_ms": 10157,
  "sample_trace_id": "1390565248288342715"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-07-03 12:24 KST
최근 발생: 2026-07-03 12:24 KST
Region: eu-central-1

Root Cause Summary#

Api::V1::UsersController#index의 조회 흐름은 (1) Elasticsearch User.search로 후보 사용자 id 목록을 얻고, (2) 그 결과에 대해 UserRepository.permission_joins가 세 개의 상관 LEFT JOIN 서브쿼리(team_user_permissions, team_group_permissions, team_system_group_permissions)를 붙여 MySQL에서 권한을 계산하는 구조다. 이번 10.2초 지연은 단일 발생, 200 응답, 동시간대 동일 endpoint의 다른 요청은 정상이라는 점에서 코드 결함이 아닌 tail-latency 이벤트로 판단된다. 가장 개연성 높은 원인은 permission_joins가 사용하는 elaborate SQL이 큰 페이지/많은 grouped_users를 가진 사용자에서 우연히 무거운 실행 계획을 탄 경우, 또는 그 시점 Elasticsearch/DB의 순간적 slow response다 — 결정적 로그 증거는 부족하다 (uncertain -- needs verification).

Technical Analysis#

Code Path#

Entry point: controller action.

app/controllers/api/v1/users_controller.rb:15-24ruby

def index
  user_query_option = Cupix::QueryOption::User.new(get_query_option, params)
  users = repository_instance.search(user_query_option)

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

repository.search는 BaseRepository의 공통 흐름을 탄다. 먼저 Elasticsearch를 호출하고, 그 결과에 permission_joins로 MySQL 권한 계산을 결합한다.

app/repositories/base_repository.rb:70-98ruby

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
  rescue Elasticsearch::Transport::Transport::Errors::BadRequest => e
    ...
  rescue Elasticsearch::Transport::Transport::ServerError => e
    raise unless e.message.start_with?('[429]')
    ...

_search는 Elasticsearch에 실제 쿼리를 던진다.

app/repositories/user_repository.rb:293-345ruby

def _search(query_option = nil)
  set_query_option(query_option)

  self.query_option.query[:bool][:must] << {
    bool: {
      minimum_should_match: 1,
      should: [ { terms: { cycle_state: ['created'] } }, ... ]
    }
  }
  ...
  response = ::User.search(
    self.query_option.serializable_hash
  ).paginate(
    per_page: self.query_option.per_page,
    page: self.query_option.page
  )

  set_response(response)
end

가장 무거운 부분은 permission_joins의 SQL이다. 사용자당 3개의 LEFT JOIN 서브쿼리(팀 단위 권한, 그룹 단위 권한, 시스템 그룹 권한)를 붙이고 GROUP BY id로 집계한다.

app/repositories/user_repository.rb:210-265ruby

def self.permission_joins(record, current_user, select: nil, **kwargs)
  ...
  record.joins("
    LEFT JOIN (
      SELECT team_id, permission
      FROM team_permissions
      WHERE team_permissions.accessor_id = #{sanitized_user_id}
        AND team_permissions.accessor_type = 'User'
      ) AS team_user_permissions
        ON team_user_permissions.team_id = users.team_id

    LEFT JOIN (
      SELECT team_id, permission
      FROM team_permissions
        LEFT JOIN grouped_users
          ON grouped_users.group_id = team_permissions.accessor_id
          AND grouped_users.user_id = #{sanitized_user_id}
      WHERE team_permissions.accessor_type = 'Group'
        AND grouped_users.user_id = #{sanitized_user_id}
      ) AS team_group_permissions
      ON team_group_permissions.team_id = users.team_id

    LEFT JOIN (
      ... system group permissions ...
    )
  ").group('id').select(_select).where("
    GREATEST(
      IFNULL(team_user_permissions.permission, 0),
      IFNULL(team_group_permissions.permission, 0),
      IFNULL(team_system_group_permissions.permission, 0)
    ) > 0
  ")
end

Failure point (potential): permission_joins의 서브쿼리는 current_user가 속한 그룹 수, 팀 수, 그리고 결과 record 크기에 비례해 무거워진다. .group('id') 및 GREATEST(...) where 절은 인덱스 사용을 제약할 수 있다. Elasticsearch 쪽 latency 역시 후보다 — _search가 반환한 후 permission_joins 결과에 대해 contents.records가 다시 호출되므로 두 스토리지에 왕복이 있다.

기대 동작: 200-1000ms 범위 응답 (동시간 다른 요청과 유사). 실제 동작: 10.2초 응답. 200 반환. 예외 없음.

Log Evidence#

Datadog query used (info level, resource name):

text

service:cupixworks-api "Api::V1::UsersController#index"
time range: 2026-07-03T03:22:00Z to 2026-07-03T03:27:00Z

이번 slow 요청 로그 항목:

json

{
  "timestamp": "2026-07-03 12:24:51 KST",
  "status": "info",
  "message": "[200] GET /api/v1/users (Api::V1::UsersController#index)"
}

동일 endpoint의 인접 요청들은 초당 여러 건이 정상 처리됨 (아래는 12:24:52 ~ 12:26:56 사이 발췌):

text

2026-07-03 12:24:52  [200] GET /api/v1/users
2026-07-03 12:24:52  [200] GET /api/v1/users
2026-07-03 12:24:53  [200] GET /api/v1/users
2026-07-03 12:25:09  [200] GET /api/v1/users
2026-07-03 12:25:14  [200] GET /api/v1/groups/7166/users
...
2026-07-03 12:26:56  [200] GET /api/v1/users

에러 레벨 로그 (같은 시간대, eu-central-1 리전, upstream 이슈 확인용):

json

{
  "timestamp": "2026-07-03 12:24:28 KST",
  "status": "error",
  "class": "OpcOperation",
  "function": "get_opc_api_access_token",
  "message": "[OpcOperation] Failed to get OPC API access token: {\"errorCode\":\"ICS-11388\",\"status\":\"HTTP 409 Conflict\",\"title\":\"Service Instance has been stopped and is unavailable at this time...\"}"
}

동시간대 warn: NotFound - attributes_in_database가 다수. Pano, Group, ElementTrace의 _update_document에서 발생, User 인덱스와는 직접 무관하나 ES 재인덱싱 부하가 있었음을 시사.

Datadog trace id로 직접 조회 시도는 결과 없음:

text

service:cupixworks-api @dd.trace_id:1390565248288342715
Found 0 logs

@duration:>5000000000 (5초 이상 ns) 필터 역시 결과 없음:

text

service:cupixworks-api "Api::V1::UsersController#index" @duration:>5000000000
Found 0 logs

이는 info-level Rails access log에는 duration 필드가 별도 태깅되지 않아 log에서 slow 요청 후보를 직접 뽑을 수 없다는 뜻이다 — cluster는 APM trace 기반으로 검출된 것이며 log 상관관계로는 확인이 불가능하다. uncertain -- needs verification (실제 소요된 span breakdown은 APM UI에서 trace id 1390565248288342715로 열어봐야 확정 가능).

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	`permission_joins`의 무거운 SQL이 특정 요청(큰 페이지 또는 grouped_users 많은 사용자)에서 slow plan을 탐	`user_repository.rb:210-265`의 3중 LEFT JOIN + GROUP BY 구조; 응답 200 (예외 없음)은 SQL 완료를 시사	Slow query 로그를 확인하지 못함 — DB slow log 미확보	Inconclusive
H2	Elasticsearch `User.search` 응답이 순간적으로 지연	동시간 다른 모델에서 `NotFound - attributes_in_database` warn 다수, ES 인덱싱 부하 정황	User 인덱스에서 warn 없음; ES 429/BadRequest도 없음	Inconclusive
H3	코드 결함 (nil handling, N+1 등)로 인한 시스템적 지연	없음	동시간 동일 endpoint 다른 요청은 정상; 단 1건 발생	Rejected
H4	Upstream 의존성 (OPC integration) 장애로 인한 지연	12:23-12:24 사이 OPC 409 에러 발생	Users endpoint 코드 경로는 OPC/IntegrationRepository를 호출하지 않음 (`users_controller.rb`/`user_repository.rb`에서 참조 없음)	Rejected
H5	Tail latency (GC pause, connection pool wait, network jitter)	단 1건, 200 응답, 인접 요청 정상 — tail latency의 전형적 패턴	직접적인 GC/pool/network 로그 증거 미확보	Confirmed (leading)

Fix Recommendation#

즉시 조치 (Critical)#

없음. 단일 발생 tail-latency 이벤트로 즉각 조치할 코드 문제로 보이지 않는다. Trace id 1390565248288342715를 APM UI에서 열어 span breakdown(ES vs MySQL vs Ruby/serializer)을 확인해 병목이 실제 어디였는지 먼저 확정할 것.

단기 개선 (1주 이내)#

APM trace 확인 결과 MySQL span이 지배적이라면, app/repositories/user_repository.rb:210-265의 permission_joins 서브쿼리에 대해 slow query log를 수집해 실행 계획 확인. 필요 시 team_permissions(accessor_id, accessor_type), grouped_users(user_id, group_id) 인덱스 커버리지 검토.
ES span이 지배적이라면, _search가 던지는 쿼리에 대해 slow query log를 확인하고 index-level circuit breaker/query cache 상태 점검.
Api::V1::UsersController#index용 별도 SLO/burn-rate 알림 설정 (예: p95 > 2s, p99 > 5s가 5분 지속).

장기 개선 (재발 방지)#

permission_joins 결과를 매 요청 계산하는 대신, 조회 빈도가 높은 권한 조합에 대해 materialized view 또는 캐시(예: Redis) 도입 검토.
대용량 team/group에서의 pagination 상한선 정책 (per_page 강제 상한) 검토.

Monitoring#

Datadog widget에 그대로 넣어 사용할 timeseries 쿼리 (writing-datadog-monitoring-queries 규칙 따름):

Users#index p95 latency (region별):

text

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::userscontroller#index} by {region}

Users#index p99 latency (region별):

text

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::userscontroller#index} by {region}

Users#index 5초 초과 요청 수 (region별, hit count):

text

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::userscontroller#index,@duration:>5s} by {region}.as_count()

전체 API p95 (baseline 비교용):

text

p95:trace.rack.request.duration{service:cupixworks-api} by {resource_name}

Risk Assessment#

Risk level: low — 단발성 tail latency, 200 응답, 사용자 영향 미미.
예상 복잡도: trivial — 확인/모니터링 강화 위주. 코드 변경은 APM span 확인 후 결정.