Api::V1::RoomsController#index (avg 1006ms, max 1006ms)

RCA: Api::V1::RoomsController#index Latency (1006ms)

Overview#

What Happened#

2026-05-26 22:10 UTC, ap-southeast-2 리전의 cupixworks-api에서 Api::V1::RoomsController#index 요청이 1006ms가 소요되었다. DB 시간은 21ms에 불과했으며, 나머지 ~984ms는 Cognito 인증 및 UserFactory.update_user_groups! 호출에서 소비되었다.

Quick Facts#

Field	Value
resource_name	`Api::V1::RoomsController#index`
top_frame	`lib/cupix/auth/verification.rb:81` (Cognito get_user_by_access_token)
env	production, ap-southeast-2
deploy	`production-ap-southeast-2-20260526t0827z0-dd7bd097-cupixworks`

Timeline#

2026-05-26T22:10:47Z — 요청 시작 (GET /api/v1/reviews/dpidjv/rooms)
2026-05-26T22:10:50Z — 요청 완료 (1005.26ms, HTTP 200)
2026-05-26T22:10:52Z — 동일 사용자에 대해 UserFactory.update_user_groups! 로그 다수 확인 (여러 Puma worker PID)
2026-05-27T00:00:00Z — RCA 분석 시작

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::RoomsController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1006,
  "max_ms": 1006,
  "sample_trace_id": "3883801996582300744"
}

Impact#

Service: cupixworks-api
발생 횟수: 1
최초 발생: 2026-05-26T22:10:47.862Z
최근 발생: 2026-05-26T22:10:47.862Z

Root Cause Summary#

Cognito 인증 과정에서 get_user_by_access_token 캐시가 만료된 상태에서 Cupix::Aws::Cognito.client() 메서드가 STS AssumeRole + Cognito API 호출을 동기적으로 수행하면서 ~500-700ms가 소비되었다. 이후 Verification.update_user_info → UserFactory.update_user_groups!에서 추가 DB 쿼리(team.groups, provisioned_groups, group.users.include? 등)와 Elasticsearch _update_document 호출이 발생하여 총 ~984ms의 비-DB 지연이 발생했다. 동시에 같은 호스트에서 ES NotFound - attributes_in_database 경고가 다수 발생하고 있어 ES 클러스터 부하도 지연에 기여했다.

Technical Analysis#

Code Path#

Entry point: app/controllers/concerns/verification_controller.rb:15 — authenticate! before_action
Authentication: lib/cupix/auth/verification.rb:55 — verify_jwt_access_token! (Rails.cache.fetch로 캐싱, 캐시 미스 시 Cognito JWT verify)
Cognito API call: lib/cupix/auth/verification.rb:81 — Cognito.get_user_by_access_token (캐시 미스 시 STS + Cognito API)
Group provisioning: lib/cupix/auth/verification.rb:300-301 — update_user_info → update_user_groups!
Controller action: app/controllers/api/v1/rooms_controller.rb:12 — repository_instance.search (ES 쿼리 + permission joins)

인증 단계 — STS AssumeRole + Cognito (주요 병목)

lib/cupix/aws/cognito.rb:9-27ruby

def client(region: nil)
  region ||= Cupix::Tesla.region

  sts_client = ::Aws::STS::Client.new(region: region)
  assumed_role = sts_client.assume_role(
    role_arn: $AWS.fetch(:cognito).fetch(:role),
    role_session_name: 'CognitoSession'
  )
  credentials = assumed_role[:credentials]

  ::Aws::CognitoIdentityProvider::Client.new(
    region: region,
    credentials: ::Aws::Credentials.new(
      credentials[:access_key_id],
      credentials[:secret_access_key],
      credentials[:session_token]
    )
  )
end

client() 메서드가 호출될 때마다 STS AssumeRole을 실행한다. 이는 네트워크 왕복 시간을 포함하여 ap-southeast-2에서 ~200-400ms가 소요될 수 있다. 캐싱이 전혀 없다.

Cognito 사용자 조회 (캐시 미스 시)

lib/cupix/aws/cognito.rb:203-217ruby

def get_user_by_access_token(access_token: nil, sub: nil)
  sub ||= ::JWT.decode(access_token, nil, false).first['sub']

  Rails.cache.fetch(user_cache_key(sub), expires_in: 1.hour) do
    Cupix::Logger.info("Fetching an user from Cognito: #{sub}", function: __method__, module: 'Cupix::Aws', class: 'Cognito')

    response = client.get_user(access_token: access_token)
  rescue ::Aws::CognitoIdentityProvider::Errors::NotAuthorizedException
    raise Cupix::Errors::Unauthorized.new(code: 'AUTH20013', reason: 'Invalid access token')
  else
    Cupix::Aws::Cognito::UserResponse.new(
      user_response_hash(response)
    )
  end
end

캐시 미스 시 client를 호출(STS AssumeRole) → get_user API 호출. 두 번의 외부 네트워크 호출이 직렬로 실행된다.

매 요청마다 실행되는 group provisioning

lib/cupix/auth/verification.rb:296-305ruby

def update_user_info(user, user_response)
  user.firstname = user_response.given_name if user_response.given_name.present?
  user.lastname = user_response.family_name if user_response.family_name.present?

  user_factory = ::UserFactory.new
  user_factory.update_user_groups!(user, user_response)

  # NOTE: there is no way to detect the user is created from OIDC
  #       so not to update `cognito_user_id` and `cognito_external_user_id``
end

update_user_info는 Cognito 인증된 active 사용자의 모든 요청에서 호출된다 (verification.rb:114). Group provisioning은 team.groups.untrashed, provisioned, group.users.include? 등 다수의 DB 쿼리를 수반한다.

app/factories/user_factory.rb:82-143ruby

def update_user_groups!(user, cognito_user)
  custom_groups = if cognito_user.respond_to?(:groups)
                    # ... parse groups
                  end

  team_groups = user.team.groups.untrashed        # DB query
  provisioned_groups = team_groups.provisioned     # DB query (or scope filter)
  group_type = GroupType.find_by_code('normal')    # DB query

  custom_groups.each do |group_name|
    group = team_groups.find { |g| g.name == group_name }
    group.update(creation_method: 'provisioned')   # DB write + ES index
    group.users << user unless group.users.include?(user)  # DB query + possible write
  end

  provisioned_groups.each do |group|
    group.users << user unless group.users.include?(user)  # DB query per group
  end
  # ...
end

Log Evidence#

Datadog 쿼리:

text

service:cupixworks-api @http.url:*rooms* @duration:>500ms env:production

요청 로그:

json

{
  "timestamp": "2026-05-26T22:10:50.077Z",
  "method": "GET",
  "path": "/api/v1/reviews/dpidjv/rooms",
  "controller": "Api::V1::RoomsController#index",
  "status": 200,
  "duration": 1005.26,
  "db": 21.23,
  "view": 0.08,
  "host": "ip-10-1-81-184.ap-southeast-2.compute.internal",
  "params": { "per_page": 2, "review_key": "dpidjv", "fields": ["id"] },
  "pagination": { "total_entries": 0, "total_page": 1 },
  "user": "michael.battah@naylorlove.co.nz",
  "user_id": 1780,
  "team": "naylorlove",
  "auth_method": "COGNITO"
}

Group provisioning 로그 (동일 사용자, 2초 후):

text

service:cupixworks-api @usr.id:1780 UserFactory

json

{
  "timestamp": "2026-05-26T22:10:52.675Z",
  "message": "Custom groups found for user 1780: [c36571bb-a1c9-4c51-968c-08e70cae2c23]",
  "class": "UserFactory",
  "function": "update_user_groups!"
}

json

{
  "timestamp": "2026-05-26T22:10:52.8Z",
  "message": "User 1780 added to group c36571bb-a1c9-4c51-968c-08e70cae2c23 #971",
  "class": "UserFactory",
  "function": "update_user_groups!",
  "pids": [13359, 13363, 13367]
}

ES 경고 (동일 시간대):

text

service:cupixworks-api status:warn NotFound attributes_in_database

json

{
  "timestamp": "2026-05-26T22:10:52Z",
  "level": "WARN",
  "message": "NotFound - attributes_in_database",
  "class": "Group",
  "function": "_update_document"
}

시간 분배 분석:

총 요청 시간: 1005ms
DB 시간 (Rails 집계): 21ms
View 시간: 0.08ms
비계정 시간 (authentication + group provisioning): ~984ms

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	Cognito `get_user_by_access_token` 캐시 미스 시 STS AssumeRole + Cognito API 호출 지연	`client()` 메서드가 매 호출마다 STS AssumeRole 실행 (`cognito.rb:12-14`), 캐시 만료 후 첫 호출에서 지연 발생. DB 시간 21ms로 컨트롤러 자체는 빠름	—	Confirmed
H2	`update_user_groups!`에서 다수의 DB + ES 쿼리로 추가 지연	동일 사용자에 대해 3개 Puma worker PID에서 동시 group provisioning 로그 확인. ES `_update_document` NotFound 경고 발생	단독으로는 984ms 설명 불가 (DB 21ms) — H1과 복합 원인	Confirmed (contributing)
H3	RoomsController#index의 ES 쿼리 또는 permission_joins가 느림	`permission_joins`에 15+ LEFT JOIN 존재	이 요청의 결과가 0건 (total_entries: 0), DB 시간 21ms로 쿼리 자체는 빠름	Rejected
H4	ap-southeast-2 리전의 네트워크 지연 (cross-region Cognito 호출)	ap-southeast-2에서 발생, Cognito User Pool이 다른 리전에 있을 경우 추가 latency	Cognito User Pool 리전 미확인 — uncertain	Inconclusive

Fix Recommendation#

즉시 조치 (Critical)#

lib/cupix/aws/cognito.rb:9-27 — client() 메서드에 STS credentials 캐싱 추가. AssumeRole 결과를 Rails.cache에 TTL(예: 50분)로 저장하여 매 호출마다 STS API를 호출하지 않도록 한다.

단기 개선 (1주 이내)#

lib/cupix/auth/verification.rb:296-305 — update_user_info 내 update_user_groups! 호출을 매 요청이 아닌 조건부로 변경. 예: 마지막 group sync 이후 일정 시간(5-10분)이 경과한 경우에만 실행하도록 user 레코드에 groups_synced_at 타임스탬프를 추가.
app/factories/user_factory.rb:109 — group.users.include?(user) 호출이 N+1 쿼리를 유발할 수 있으므로 group.user_ids를 미리 로드하여 메모리에서 비교.

장기 개선 (재발 방지)#

Cognito group provisioning을 비동기 작업(Sidekiq worker)으로 분리하여 인증 요청의 critical path에서 제거.
Cupix::Aws::Cognito.client() 전체를 thread-safe 싱글턴으로 리팩토링하고 credential rotation을 자동 처리하도록 변경.

Monitoring#

update_user_groups! 실행 시간을 별도 메트릭으로 추적:

text

service:cupixworks-api @message:"Provisioned user*" | stats avg(@duration) by @usr.id

STS AssumeRole 호출 빈도 모니터링:

text

service:cupixworks-api "Fetching an user from Cognito" | timeseries count by host

RoomsController#index P95 latency 알림 설정 (threshold: 500ms)

Risk Assessment#

Risk level: low
예상 복잡도: standard