RCA: Api::V1::BookmarksController#index Latency (1042ms)

Overview#

What Happened#

2026-05-26 05:39:42 UTC에 cupixworks-api 서비스의 Api::V1::BookmarksController#index 엔드포인트에서 1042ms 응답 지연이 발생했다. ap-southeast-1 리전에서 단일 요청이 감지되었으나, 동일 시간대에 같은 사용자 및 다른 사용자의 요청에서도 유사한 지연(664~927ms)이 반복적으로 확인되어 시스템적 이슈로 판단된다.

Quick Facts#

Timeline#

1. 2026-05-26T05:39:42Z — BookmarksController#index 요청 시작 (trace_id: 2979105533828777353)
2. 2026-05-26T05:39:43Z — 응답 완료 (200 OK, 1039.64ms 소요, 결과 0건)
3. 2026-05-26T05:39:45Z — 동일 사용자의 /bookmarks/team 요청도 927ms 소요
4. 2026-05-26T05:41:01Z — 동일 사용자의 재요청에서도 664ms 소요
5. 2026-05-27 — RCA 분석 완료

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::BookmarksController#index",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1042,
  "max_ms": 1042,
  "sample_trace_id": "2979105533828777353"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (collector 감지 기준, 동일 시간대 유사 지연 5건 추가 확인)
• 최초 발생: 2026-05-26T05:39:42.172Z
• 최근 발생: 2026-05-26T05:39:42.172Z

Root Cause Summary#

BookmarksController#index의 1042ms 지연은 Cognito 인증 과정의 원격 API 호출 지연이 주요 원인이다. Datadog 로그에서 총 duration 1039.64ms 중 DB 시간은 18.5ms, view 시간은 0.12ms에 불과하며, 약 1020ms가 미설명 상태로 Rails middleware/authentication 레이어에서 소비되었다. Cupix::Auth::Verification#verify_authenticated_request!가 Cupix::Aws::Cognito.get_user_by_access_token을 호출할 때, 캐시 미스 시 AWS Cognito API에 대한 원격 호출이 발생하며, ap-southeast-1 리전에서 Cognito 엔드포인트까지의 네트워크 왕복 시간이 전체 지연의 대부분을 차지한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/bookmarks_controller.rb:11 (index action)
• Authentication: app/controllers/concerns/verification_controller.rb:15 (authenticate! before_action)
• Cognito API call: lib/cupix/auth/verification.rb:81 (get_user_by_access_token)
• Cognito client: lib/cupix/aws/cognito.rb:203-217 (Rails.cache.fetch with 1h TTL)
• Repository search: app/repositories/base_repository.rb:70-112
• Permission joins: app/repositories/bookmark_repository.rb:36-200

1단계: 인증 (주요 병목)

verified_access_token = self.class.verify_jwt_access_token!(access_token: @access_token)

if verified_access_token.issuer == Cupix::Auth::Issuers::Cupixworks
  return verified_access_token.issuer.signin!(access_token: verified_access_token.access_token, verified: true)
end

begin
  # ...
  user_response = Cupix::Aws::Cognito.get_user_by_access_token(access_token: access_token, sub: sub)

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

캐시 TTL이 1시간이므로, 캐시 만료 후 첫 요청에서 Cognito GetUser API 원격 호출이 발생한다. ap-southeast-1에서 Cognito 리전(대부분 us-east-1)으로의 왕복 시간이 700~1000ms에 달할 수 있다.

2단계: JWT 검증 (보조 병목)

Rails.cache.fetch("cupix:auth:verification:verify_jwt_access_token:#{access_token}", expires_in: expires_in) do
  Cupix::Logger.info("Verifying JWT access token: #{access_token}", function: __method__, module: 'Cupix::Auth::Verification')

  registered_issuers = [Cupix::Auth::Issuers::Cognito, Cupix::Auth::Issuers::Cupixworks]
  decoded_token = nil
  _issuer = nil

  registered_issuers.each do |issuer|
    next unless issuer.match?(iss)

    decoded_token = issuer.verify!(access_token)
    _issuer = issuer
  end

  ::Cupix::Auth::VerifiedAccessToken.new(access_token: access_token, decoded_access_token: decoded_token, issuer: _issuer)
end

JWT 검증도 캐시가 만료되면 Cognito JWKS 엔드포인트에 네트워크 요청을 보낸다. 두 캐시(JWT 검증 + GetUser)가 동시에 만료되면 지연이 합산된다.

3단계: 비즈니스 로직 (18.5ms — 정상 범위)

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  return record if kwargs[:skip_join]

  if select.present?
    _select = ApplicationRecord.sanitize_sql(select)
  else
    _select = "bookmarks.*,
    MAX(review_user_permissions.permission) AS review_user_permission,

11개 LEFT JOIN 서브쿼리를 사용하는 permission_joins는 복잡하지만, 이 요청에서는 결과가 0건이므로 DB 시간이 18.5ms로 측정되었다. 결과가 많을 경우 추가 지연 가능성이 있으나, 이번 인시던트의 병목은 아니다.

Log Evidence#

Datadog에서 사용한 쿼리:

service:cupixworks-api trace_id:2979105533828777353

핵심 로그 (trace ID 2979105533828777353):

{
  "message": "[200] GET /api/v1/reviews/dnxj2h/bookmarks/me (Api::V1::BookmarksController#index)",
  "duration": 1039.64,
  "db": 18.5,
  "view": 0.12,
  "serialization": 0,
  "total_entries": 0,
  "host": "ip-10-1-82-247.ap-southeast-1.compute.internal",
  "user": "warren.allan@cupix.com",
  "team": "aceplp",
  "params": {"review_key": "dnxj2h", "page": 1, "per_page": 100},
  "auth_method": "COGNITO"
}

동일 시간대 추가 확인된 지연 요청:

service:cupixworks-api "BookmarksController" @duration:>500

모든 요청에서 DB 시간은 518ms인 반면, 총 duration은 6641039ms로 미설명 시간이 650~1020ms에 달한다. 이는 인증 레이어의 외부 API 호출(Cognito)이 병목임을 강하게 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• lib/cupix/aws/cognito.rb:206 — get_user_by_access_token의 캐시 TTL을 1시간에서 더 길게(4~8시간) 연장하거나, 캐시 warming 전략 도입을 검토한다. 캐시 미스 빈도를 줄여 Cognito 원격 호출 횟수를 감소시킨다.
• lib/cupix/auth/verification.rb:55 — verify_jwt_access_token!의 캐시 TTL ([remaining_time, 300].max.seconds)이 최소 5분으로 설정되어 있어 빈번한 갱신이 발생할 수 있다. JWT 만료 시간에 가까울수록 캐시 미스가 잦아지므로, token refresh 전략을 점검한다.

단기 개선 (1주 이내)#

• ap-southeast-1 리전의 Cognito User Pool 존재 여부를 확인하고, 가능하면 동일 리전에 User Pool을 배치하여 네트워크 왕복 시간을 줄인다.
• 인증 과정에서 get_user_by_access_token 호출을 비동기로 처리하거나, stale-while-revalidate 패턴을 적용하여 캐시 만료 직후에도 즉시 이전 캐시 값을 반환하고 백그라운드에서 갱신한다.

장기 개선 (재발 방지)#

• 인증 레이어에 APM instrumentation을 추가하여 Cognito 호출 시간을 개별 span으로 추적한다. 현재는 전체 controller duration만 보이고 인증 소요 시간은 별도 측정되지 않아 분석이 어렵다.
• permission_joins의 11개 LEFT JOIN은 현재 요청에서는 병목이 아니지만, 결과가 많은 경우(100건 페이지네이션) 지연 가능성이 있으므로 권한 확인을 materialized view 또는 캐시 기반으로 재설계한다.

Monitoring#

• Cognito 인증 호출 duration 추적을 위한 custom metric 추가:

service:cupixworks-api "Fetching an user from Cognito" | measure @duration

• BookmarksController#index P95 latency 알림:

avg(last_5m):p95:trace.rack.request{service:cupixworks-api, resource_name:"Api::V1::BookmarksController#index"} > 500

• Cognito 캐시 hit rate 모니터링 (Rails.cache metrics)

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard — 캐시 TTL 변경은 trivial하나, 리전 최적화 및 stale-while-revalidate 패턴 적용은 아키텍처 검토 필요