Api::V1::WorkareasController#index (avg 1274ms, max 1274ms)

RCA: Api::V1::WorkareasController#index Latency (1274ms)

Overview#

What Happened#

2026-05-26 03:22Z에 ap-southeast-2 리전의 cupixworks-api 서비스에서 WorkareasController#index 엔드포인트가 1274ms의 응답 시간을 기록했다. 동일 시간대에 같은 리전에서 20건 이상의 slow request(500ms~2900ms)가 관찰되었으며, 대부분 0건의 결과를 반환하면서도 높은 지연시간을 보였다.

Quick Facts#

Field	Value
resource_name	`Api::V1::WorkareasController#index`
top_frame	`app/repositories/workarea_repository.rb:51`
env	production, ap-southeast-2
avg_duration	1274ms
http.status_code	200

Timeline#

2026-05-26T03:19:04Z — 동일 엔드포인트에서 최대 2907ms 지연 관찰 (review: g3wuch, team: built)
2026-05-26T03:22:18Z — 대표 span 기록: 1274ms (review: icruxi, team: shape, user: William Gorgas)
2026-05-26T03:50:49Z — 이후에도 700~900ms 수준의 slow request 지속 발생

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::WorkareasController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1274,
  "max_ms": 1274,
  "sample_trace_id": "3185257514841865103"
}

Impact#

Service: cupixworks-api
발생 횟수: 1 (threshold 초과 기준), 실제 slow request 20+건 관찰
최초 발생: 2026-05-26T03:22:18.319Z
최근 발생: 2026-05-26T03:22:18.319Z
영향 범위: ap-southeast-2 리전의 다수 팀 (shape, naylorlove, pace, built, forida-demo)

Root Cause Summary#

WorkareasController#index의 지연은 COGNITO 인증 미들웨어에서의 사용자 그룹 프로비저닝 오버헤드와 11개 LEFT JOIN 서브쿼리로 구성된 permission_joins SQL의 복합 작용으로 발생한다. DB 시간은 58ms에 불과하지만 전체 응답 시간은 1274ms로, 나머지 ~1200ms는 인증/인가 미들웨어 레이어(COGNITO 토큰 검증 + UserFactory#update_user_groups! 호출)에서 소비된다. 특히 SPA 페이지 로드 시 다수의 병렬 API 호출 중 첫 번째 요청이 인증 오버헤드를 집중적으로 받는 패턴이 확인되었다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/workareas_controller.rb:10
Repository search: app/repositories/base_repository.rb:70
Elasticsearch query + MySQL permission joins: app/repositories/workarea_repository.rb:266-334
Permission joins (11 LEFT JOINs): app/repositories/workarea_repository.rb:51-231

1. Controller action — 요청 진입점:

app/controllers/api/v1/workareas_controller.rb:10-19ruby

def index
  workarea_query_option = Cupix::QueryOption::Workarea.new(get_query_option, params)
  workareas = repository_instance.search(workarea_query_option)

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

2. BaseRepository#search — 2단계 검색 (ES → MySQL + permission):

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

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?)
    elsif self.review_id.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
      contents = self.class.permission_joins(self.class.default_joins(self.response.records), self.current_user, skip_join: _skip_join?)
    end
  end
  # ...
end

Elasticsearch 쿼리 결과의 record ID 목록을 MySQL로 재조회하면서 permission_joins를 적용한다. 결과가 0건이더라도 ES 쿼리와 permission SQL은 항상 실행된다.

3. Permission joins — 11개 LEFT JOIN 서브쿼리:

app/repositories/workarea_repository.rb:51-79ruby

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  _select = "
    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(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(GREATEST(
      IFNULL(facility_user_permissions.permission, 0),
      ...
    )) AS applied_permission"

app/repositories/workarea_repository.rb:211-230ruby

  ").group('id').select(_select).where("
    GREATEST(
      IFNULL(review_user_permissions.permission, 0),
      IFNULL(review_group_permissions.permission, 0),
      IFNULL(review_public_permissions.permission, 0)
    ) > 0
    OR
      GREATEST(
        IFNULL(review_user_permissions.permission, 0),
        ...
        IFNULL(team_system_group_permissions.permission, 0)
      ) > 1
  ")

이 쿼리는 review_permissions, facility_permissions, workspace_permissions, team_permissions, grouped_users 테이블을 11번 LEFT JOIN하여 사용자 권한을 평가한다. 그러나 Datadog 로그에서 DB 시간은 58ms로, 이 SQL 자체가 1274ms의 주요 원인은 아니다.

4. 실제 병목: COGNITO 인증 미들웨어

Datadog 로그 분석 결과:

전체 요청 시간: 1272ms
DB 시간: 58ms
View 렌더링: 0.07ms
Serialization: 0ms
미설명 시간: ~1214ms → 인증/인가 미들웨어에서 소비

동일 초(03:22:20Z)에 UserFactory#update_user_groups!가 user 4473(William Gorgas)에 대해 12건 이상 연속 호출된 것이 확인되었다. 이는 COGNITO 토큰 검증 후 사용자 그룹 동기화 과정이다.

Log Evidence#

Datadog에서 사용한 쿼리:

text

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

대표 slow request 로그 (03:22:20Z):

json

{
  "timestamp": "2026-05-26T03:22:20.273Z",
  "duration_ms": 1272.44,
  "db_runtime_ms": 58.42,
  "view_runtime_ms": 0.07,
  "http.method": "GET",
  "http.url": "/api/v1/reviews/icruxi/workareas",
  "http.status_code": 200,
  "total_entries": 0,
  "host": "ip-10-1-145-251.ap-southeast-2.compute.internal",
  "user": "william.gorgas@shape.com.au",
  "team": "shape",
  "auth_method": "COGNITO"
}

동일 시간대 slow request 패턴 (모두 total_entries: 0 반환):

text

03:19:04Z - 2907ms (DB: 21ms) - review: g3wuch, team: built
03:22:16Z -  816ms (DB: 35ms) - review: icruxi, team: shape
03:22:20Z - 1272ms (DB: 58ms) - review: icruxi, team: shape  ← 대표 span
03:26:40Z -  998ms (DB: 10ms) - review: fntui4, team: naylorlove
03:30:20Z -  947ms (DB: 14ms) - review: g5rqou, team: naylorlove
03:38:40Z -  887ms (DB: 11ms) - review: 6oba41, team: naylorlove

핵심 관찰: DB 시간(10~~58ms)과 총 응답 시간(816~~2907ms) 사이에 큰 격차가 있으며, 이 격차는 인증 미들웨어에서 발생한다.

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	COGNITO 인증 미들웨어의 `UserFactory#update_user_groups!`가 요청마다 사용자 그룹 프로비저닝을 수행하여 지연 발생	동일 초에 12건의 `update_user_groups!` 호출 확인, DB 58ms vs 전체 1272ms (격차 1214ms), 모든 slow request가 COGNITO 인증 사용	DB 시간에 인증 쿼리가 포함되었을 수 있음	Confirmed
H2	`permission_joins`의 11개 LEFT JOIN SQL 쿼리가 느림	복잡한 SQL 구조 (11 LEFT JOIN + GREATEST + GROUP BY)	DB 시간이 10~58ms로 매우 낮음, 결과 0건인 요청에서도 동일한 높은 지연	Rejected
H3	Elasticsearch 쿼리 지연	2단계 검색 구조 (ES → MySQL)	DB 시간 메트릭에 ES 쿼리는 미포함이지만, 0건 반환 요청의 ES 쿼리는 매우 빠를 것 (빈 결과), 전체 지연 패턴 설명 불가	Rejected
H4	ap-southeast-2 리전의 인프라 이슈 (네트워크 지연, 리소스 경합)	20건 이상의 slow request가 모두 ap-southeast-2에서 발생	다수 팀/호스트에서 동시 발생하여 단일 호스트 문제 아님, DB/ES 자체는 빠름	Inconclusive

Fix Recommendation#

즉시 조치 (Critical)#

UserFactory#update_user_groups!에서 불필요한 그룹 동기화 방지를 위해 캐싱 또는 조건부 실행 도입
- 마지막 동기화 이후 변경이 없으면 skip하는 로직 추가 검토
- 인증 미들웨어에서 그룹 프로비저닝 결과를 요청 단위 또는 TTL 기반 캐싱

단기 개선 (1주 이내)#

COGNITO 토큰 검증 결과의 Redis 캐싱 도입: 토큰 유효 기간 내에는 재검증하지 않도록
SPA 페이지 로드 시 병렬 API 호출에서 첫 요청이 인증 비용을 전담하는 패턴 개선: 인증 결과를 같은 세션의 후속 요청에 공유
WorkareasController#index에서 review 기반 조회 시 결과가 0건인 경우의 early return 최적화 검토

장기 개선 (재발 방지)#

Permission 체크 아키텍처를 SQL JOIN 기반에서 캐싱된 permission matrix 또는 사전 계산된 ACL 방식으로 전환
인증/인가 레이어의 성능 메트릭을 별도 span으로 분리하여 APM에서 가시성 확보
ap-southeast-2 리전의 COGNITO 엔드포인트 응답 시간 모니터링 추가

Monitoring#

COGNITO 인증 미들웨어 소요 시간을 별도 custom span으로 계측
Datadog 쿼리 예시:

text

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

text

service:cupixworks-api @message:"update_user_groups" env:production

알림 조건: avg(duration) > 1000ms for WorkareasController#index over 5분 window

Risk Assessment#

Risk level: low
예상 복잡도: standard
사용자 체감 영향: 페이지 로드 시 1~3초 지연이 발생하지만 기능적 오류는 없음 (HTTP 200 반환). 다만 반복적으로 발생하여 UX 저하 요인.