RCA: Api::V1::AssetsController#show latency outlier (avg 14192ms)

Overview#

What Happened#

2026-06-27 00:34 KST (2026-06-26 15:34 UTC) 시점에 cupixworks-api (us-west-2, tenant cupix)의 Api::V1::AssetsController#show 요청 한 건이 14,192ms (≈ 14.2초) 만에 응답한 latency outlier가 감지되었다. 같은 시간 윈도우의 다른 Asset show 요청들은 모두 30ms 내외로 정상 처리되었고, 5xx 에러나 경고 로그도 확인되지 않았다. 단발성 슬로우 쿼리/리소스 경합 가능성이 높다.

Quick Facts#

Affected Teams#

영향 범위는 단일 요청 1건이고, 같은 시간대의 다른 Asset show 요청은 정상 처리되었다. 어떤 팀이 영향을 받았는지 정확히 특정할 수 없어 표는 생략한다 (단발성 outlier로 추정).

Timeline#

1. 2026-06-27 00:34:03 KST — Api::V1::AssetsController#show 요청이 14,192ms 만에 종료, APM에서 latency span 감지 (trace 5950736698621684397).
2. 2026-06-27 00:34:03 KST — 같은 윈도우 내 다른 Asset show 요청은 평균 ~28ms / db ~12ms로 정상 (예: 5kuqwv1v8fvt, request_id c72ff0f3-9246-4279-8ace-6f40a63c9c98).
3. 2026-06-27 00:34 KST — error-sweeper 가 latency cluster d51c393c-9fb5-43ad-86a7-d34e9d124576 생성, status-board 상 svc:cupixworks-api::unknown 인시던트 (2026-06-26-svc-cupixworks-api--unknown-3)에 묶임.
4. 2026-06-27 00:34 KST — 이후 신규 occurrence 미감지, status-board 상 resolved 처리됨.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::AssetsController#show",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 14192,
  "max_ms": 14192,
  "sample_trace_id": "5950736698621684397"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-27 00:34 KST
• 최근 발생: 2026-06-27 00:34 KST

요청 1건이 정상 대비 약 500배 느린 응답시간(28ms → 14.2s)을 기록. 같은 시점의 다른 Asset show 요청은 정상이므로 사용자 전반에 미치는 영향은 제한적이지만, 호출 측이 짧은 클라이언트 타임아웃을 갖는 경우(예: cupix-agent — 윈도우 내 user_agent: cupix-agent 다수 확인) 단일 요청 실패로 인지될 수 있다.

Root Cause Summary#

해당 요청은 Api::V1::AssetsController#show → set_asset → AssetRepository#show(params[:key]) → BaseRepository.show 경로를 타며, 이 경로의 최종 단계는 permission_joins(workspace/facility/team/review 권한을 위한 8~9개의 LEFT JOIN 서브쿼리)와 default_joins(workspaces / users / teams / captures LEFT JOIN, 추가 select)를 합친 후 merge(scope).first로 단일 행을 조회한다. 같은 시간 윈도우의 다른 Asset show 요청 로그에서 db ≈ 12ms, 전체 duration ≈ 28ms로 확인되는 반면 본 trace는 14,192ms이므로, 코드 결함(예: nil dereference, 무한 루프)이 아니라 DB-side outlier — 가장 가능성 높은 후보는 (1) permission_joins SQL 의 일시적 plan 악화나 통계 갱신 지연으로 인한 슬로우 쿼리, (2) Pundit.policy(current_user, model).read? 호출 또는 그 안에서 일어나는 추가 조회의 일시적 락/대기, (3) DB connection pool 또는 ActiveRecord 연결 대기로 인한 stall이다. 단발성 1건이고 동일 윈도우 내 같은 엔드포인트가 정상 동작했으므로 코드 변경보다는 인프라 측 검증과 모니터링 강화가 필요하다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/assets_controller.rb:10 (before_action :set_asset)
• Lookup: app/controllers/api/v1/assets_controller.rb:62-64 (set_asset → repository_instance.show(params[:key]))
• Repository wrapper: app/repositories/base_repository.rb:121-129 (#show → self.class.show(...))
• Heavy join + scope: app/repositories/base_repository.rb:306-343 (self.show → permission_joins(default_joins(...)) → merge(scope).first)
• Failure point (latency hot spot): app/repositories/base_repository.rb:343 — query.merge(scope).first (SELECT 실행 시점)

  protected

  def set_asset
    @model = repository_instance.show(params[:key])
  end

    query =
      if skip_permission || current_user == ::User.unauthorized_user
        where(attrs)
      elsif current_class == ::Review || (review_id || capture_id).present?
        permission_joins(default_joins(current_class), current_user, review_id: review_id || -1, capture_id: capture_id || -1).where(attrs)
      elsif current_user.present?
        permission_joins(default_joins(current_class), current_user).where(attrs)
      else
        raise Cupix::Errors::System.new(code: 'SYS30000', reason: 'current_user or review is required on Repository')
      end

    scope = current_class.visibility_scope(visibility)
    model = query.merge(scope).first

permission_joins는 workspace_user_permissions, workspace_group_permissions, facility_user_permissions, facility_group_permissions, team_user_permissions, team_group_permissions, team_system_group_permissions, review_user_permissions, review_group_permissions 등 8~9개의 LEFT JOIN 서브쿼리를 inline 조립하여 만들어진다. 정상 시 db ≈ 12ms로 처리되지만 (예: request_id c72ff0f3-9246-4279-8ace-6f40a63c9c98 로그 참조), plan 변동·MySQL 통계 갱신 지연·대용량 그룹 사용자가 포함된 사용자 컨텍스트 등에서 outlier로 폭증할 가능성이 있다:

  def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
    if select.present?
      _select = ApplicationRecord.sanitize_sql(select)
    else
      _select = "MAX(workspace_user_permissions.permission) AS workspace_user_permission,
      MAX(workspace_group_permissions.permission) AS workspace_group_permission,
      MAX(facility_user_permissions.permission) AS facility_user_permission,
      MAX(facility_group_permissions.permission) AS facility_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,
      ...

이후 권한 모델에 대해 추가로 Pundit 정책 검사가 수행되며, 정책 메서드가 추가 DB 조회를 트리거할 수도 있다 (별도 outlier 후보):

    if !skip_permission && current_user.present? && !Pundit.policy(current_user, model).read?
      raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied')
    end

    if current_user.present? && model.respond_to?(:workspace_id) && model.respond_to?(:team_id) && current_user.team_id == model.team_id
      current_user.set_current_workspace(model.workspace_id)
    end

기대 동작: permission_joins + default_joins 조회가 정상 plan으로 db ≈ 12ms 수준에서 완료되고 전체 요청은 30ms 내외로 응답. 실제 동작: 트레이스 5950736698621684397 한 건이 14,192ms 만에 종료. 같은 1분 윈도우 내의 다른 Asset show 요청들은 모두 정상 (~28ms).

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "Api::V1::AssetsController#show"

service:cupixworks-api controller:"Api::V1::AssetsController" action:show @duration:>5000

service:cupixworks-api status:error

service:cupixworks-api @trace_id:5950736698621684397

같은 윈도우(2026-06-26T15:30:00Z ~ 2026-06-26T15:40:00Z) 내 Asset show 정상 요청 샘플 — db: 12.09ms, 총 duration: 28.65ms:

{
  "message": "[200] GET /api/v1/assets/5kuqwv1v8fvt (Api::V1::AssetsController#show)",
  "controller": "Api::V1::AssetsController",
  "action": "show",
  "params": { "key": "5kuqwv1v8fvt", "fields": ["key","name","asset_type","state","resource_state","meta","cover_state","thumbnail_urls","cover_upload_url"] },
  "duration": 28.65,
  "db": 12.09,
  "view": 0.06,
  "http": { "method": "GET", "url_details": { "path": "/api/v1/assets/5kuqwv1v8fvt" }, "status_code": 200 },
  "team": { "domain": "solarturbines", "id": 1002 },
  "user": { "id": 51233, "email": "augustojose.manzoperez@solarturbines.com" },
  "request_id": "c72ff0f3-9246-4279-8ace-6f40a63c9c98",
  "user_agent": "cupix-agent",
  "tenant": "cupix",
  "environment": "production",
  "@timestamp": "2026-06-26T15:33:56.262Z"
}

기록된 사실:

• @duration:>5000(5초 초과 Asset show) 검색 결과 동일 윈도우에서 0건 — slow request에 해당하는 request log entry가 발견되지 않았다. 가능한 원인: (a) 요청이 cupix-agent/ELB의 클라이언트/엣지 타임아웃에 의해 abort되어 Rails가 lograge 라인을 emit하지 못함, (b) APM의 @duration (ns) 과 request log의 @duration (ms) 표기 차로 인한 단순 매칭 실패 — 그러나 >5000 도 여전히 trace의 14,192ms보다 작은 임계임에도 0건이므로 (a) 가능성이 더 높음.
• 같은 윈도우에서 service:cupixworks-api status:error 0건 — application exception 흔적 없음.
• trace_id 5950736698621684397 키워드 검색 0건 — 로그가 trace_id를 직접 attribute로 노출하지 않거나 lograge 라인 자체가 누락됨.
• status-board 결과: 이 클러스터는 svc:cupixworks-api::unknown 인시던트 2026-06-26-svc-cupixworks-api--unknown-3에 묶임. 같은 시간대 또 다른 클러스터(55162ccb-06e7-4abf-86e6-6720c1962d2a)가 7분 전에 발생.

배포 컨텍스트:

version:production-us-west-2-20260626t0223z0-bfdc5ebd-cupixworks
region:us-west-2
env:production

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 코드 변경 불필요. 단발성 outlier 1건이며 동일 윈도우 내 동일 엔드포인트가 정상 동작했음. 우선 인프라/DB 메트릭 확인 위주로 진행 권고:
  • app/repositories/base_repository.rb:343 라인의 쿼리에 대한 RDS Performance Insights / MySQL slow_query_log 상 동일 시각 (2026-06-26 15:34 UTC) 슬로우쿼리 존재 여부 확인.
  • APM trace 5950736698621684397 의 span 단위 breakdown 확인 — mysql.query span 의 duration 분포 / activerecord 단계 / pundit.policy 호출 단계 중 어디에서 14초가 소비되었는지 식별.

단기 개선 (1주 이내)#

• permission_joins SQL 의 정상/이상 plan 비교. Asset + 사용자 컨텍스트(team.domain=solarturbines, team.id=1002)와 같은 큰 워크스페이스에서 plan 변동이 빈번하다면 default_joins / permission_joins 의 LEFT JOIN 수를 줄이거나 일부 권한 검사를 별도 쿼리로 분리하는 방향 검토.
• Rails 측에 Rack::Timeout 또는 ActiveRecord query timeout (예: MAX_EXECUTION_TIME MySQL hint) 적용 여부 확인 — 슬로우쿼리가 14초까지 진행되도록 방치되는 것이 정상인지 확인.

장기 개선 (재발 방지)#

• 권한 매트릭스를 매 요청마다 LEFT JOIN으로 계산하는 대신, 사용자별 접근 가능 ID 집합 캐싱 (Redis / 메모리) 또는 별도 권한 서비스 분리.
• APM 기반 latency budget 설정 — Api::V1::AssetsController#show p99 SLO 를 정의하고 위반 시 알림. 단발성 14초 outlier도 자동 트레이스 캡처되도록 sampling 강화.

Monitoring#

Api::V1::AssetsController#show slow request 빈도 (proof query — 동일 outlier 재발 시 그래프에서 즉시 확인 가능):

service:cupixworks-api controller:"Api::V1::AssetsController" action:show @duration:>5000

cupixworks-api HTTP 5xx rate (요청 abort 동반 여부 감지):

service:cupixworks-api @http.status_code:[500 TO 599]

APM trace 측 5초 초과 Asset show span 카운트 (메트릭 시그널):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::AssetsController#show}.as_count()

DB query latency 평균 (DB outlier 추세):

avg:postgresql.query.time{service:cupixworks-api}

(주: 실제 DB가 MySQL 인 경우 avg:mysql.performance.query_run_time_avg{service:cupixworks-api} 등 적절한 metric 으로 교체)

Risk Assessment#

• Risk level: low — 단발성 1건, 5xx 미발생, 다른 요청 정상.
• 예상 복잡도: trivial — 즉시 코드 수정 불필요, 모니터링과 DB plan 확인 위주.