ES /docs

Api::V1::WorkspacesController#show (avg 11449ms, max 11449ms)

RCA: Api::V1::WorkspacesController#show latency spike (avg 11449ms)

Overview#

What Happened#

2026-07-16 14:28:57 KST 에 cupixworks-api production(us-west-2)에서 Api::V1::WorkspacesController#show 리소스가 단일 요청 기준 11,449ms 로 처리된 latency outlier 가 감지되었다. 상태 코드는 error/warn 이 아니라 정상 200 응답으로 완료된 slow request 이며, 동일 리소스에서 클러스터 창(14:28 KST 전후) 다른 요청들은 정상 지연 범위였다.

Quick Facts#

Field Value
resource_name Api::V1::WorkspacesController#show
cluster_type latency
avg_duration_ms 11449
max_duration_ms 11449
occurrences 1
sample_trace_id 3044730468254276793
env production, us-west-2
tenant cupix

Affected Teams#

Team / Domain Error Count Impact
cupixworks-api (workspaces GET) 1 워크스페이스 상세 페이지 로딩 지연 (11.4s) 을 겪은 단일 사용자 세션

Timeline#

  1. 2026-07-16 14:28:57 KST — 문제의 GET /api/v1/workspaces/:id 요청이 시작되어 11,449ms 뒤에 200으로 완료 (Datadog APM trace_id 3044730468254276793).
  2. 2026-07-16 14:28:47–14:32:57 KST — 같은 시간대의 다른 WorkspacesController#show 로그(Datadog info 로그)들은 모두 정상적으로 200 완료. 동시간대에 cupixworks-api status:error 로그는 Cupix::PubSub::Subscribers::UserRecipeGenerator 의 무관한 private method 'service_jwt' 실패만 다수 발생 (본 클러스터와 별개 문제).
  3. 감지 — error-sweeper collector 가 APM p95 duration > 500ms 임계에서 이 outlier 를 latency cluster 로 수집.

Error Log#

Datadog Logs

text
{
  "resource_name": "Api::V1::WorkspacesController#show",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 11449,
  "max_ms": 11449,
  "sample_trace_id": "3044730468254276793"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1
  • 최초 발생: 2026-07-16 14:28:57 KST
  • 최근 발생: 2026-07-16 14:28:57 KST

Root Cause Summary#

Api::V1::WorkspacesController#show 에서 set_workspace before_action → WorkspaceRepository.showBaseRepository.show 경로가 실행될 때, permission_joins 가 workspace 단건 조회에도 6 개의 대형 LEFT JOIN 서브쿼리 (workspace_user/group, team_user/group, team_system_group, review_public) 를 build 하여 workspace_permissions, team_permissions, grouped_users, reviews 를 조인한 뒤 GREATEST/IFNULLWHERE 절과 SELECT 절 양쪽에서 계산한다. 이 단일 요청은 특정 tenant 의 permission 스캔이 cold path 로 실행되면서 (혹은 동시 write 로 인한 lock 대기·plan 재선정) 11.4초까지 늘어난 outlier 로 판단된다. 클러스터가 단일 occurrence 인 점, 같은 분에 다른 #show 요청들이 정상 응답한 점, 동시간대 error 로그가 별개 이슈인 점으로 볼 때 systemic latency 가 아닌 permission_joins 쿼리의 tail latency (p99+ outlier) 가 root cause 이다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/workspaces_controller.rb:9before_action :set_workspace
  • set_workspace — repository 인스턴스의 show 를 호출
  • WorkspaceRepository.showBaseRepository.show — permission_joins 조합 후 .first 로 단건 조회
  • Failure point (latency source): app/repositories/workspace_repository.rb:72-174self.permission_joins 가 실행되며 6개 LEFT JOIN 서브쿼리가 매 요청마다 재구성 및 실행됨
app/controllers/api/v1/workspaces_controller.rb:9-38ruby
before_action :set_workspace, except: %i[index create untrash purge mock bulk_share bulk_unshare]

# ...

def set_workspace
  @model = repository_instance.show(params[:id])
end
app/repositories/workspace_repository.rb:16-24ruby
def self.show(id, current_user: nil, **kwargs)
  model = super

  if current_user.present? && model.present?
    current_user.set_current_workspace(model)
  end

  model
end
app/repositories/base_repository.rb:306-344ruby
def self.show(key_or_id_or_model, current_user: nil, visibility: Cyclable.visibility[:UNTRASHED], review_id: nil, capture_id: nil, skip_permission: false)
  # ...
  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
app/repositories/workspace_repository.rb:95-174ruby
record.joins("
  LEFT JOIN (
    SELECT reviews.id AS review_id, 2 AS permission
    FROM reviews
    where reviews.public_access_enabled_at IS NOT NULL
      AND reviews.id = #{sanitized_review_id}
  ) AS review_public_permissions
    ON review_public_permissions.review_id = #{sanitized_review_id}

  LEFT JOIN (
    SELECT workspace_id, permission
    FROM workspace_permissions
    WHERE workspace_permissions.accessor_id = #{sanitized_user_id}
      AND workspace_permissions.accessor_type = 'User'
    ) AS workspace_user_permissions
      ON workspace_user_permissions.workspace_id = workspaces.id
  ...
").group('id').select(_select).where("
  (
    GREATEST(
      IFNULL(team_user_permissions.permission, 0),
      IFNULL(team_group_permissions.permission, 0)
    ) = 1
    AND
      GREATEST(
        IFNULL(workspace_user_permissions.permission, 0),
        IFNULL(workspace_group_permissions.permission, 0)
      ) > 0
  )
  OR
  GREATEST(...) > 1
")
  • 기대 동작: 단건 workspace 조회는 100–300ms 이내에 완료되어야 함 (14:20–14:34 KST 창의 동일 리소스 로그는 사이 간격이 짧고 200 정상 응답).
  • 실제 동작: 이 한 건은 11,449ms 로 완료 — permission_joins 서브쿼리 계획이 cold buffer/lock/large permission set 로 인해 튄 tail latency outlier.

Log Evidence#

Datadog query used:

text
service:cupixworks-api "WorkspacesController#show"

시간창: 2026-07-16 14:20:00–14:34:39 KST (동일 분기 로그)

동시간대 정상 #show 요청 예 (본 클러스터 요청과 같은 분에 발생, 모두 200 정상 완료):

json
{
  "timestamp": "2026-07-16 14:28:47",
  "status": "info",
  "message": "[200] GET /api/v1/workspaces/1290 (Api::V1::WorkspacesController#show)"
}
{
  "timestamp": "2026-07-16 14:29:32",
  "status": "info",
  "message": "[200] GET /api/v1/workspaces/5716 (Api::V1::WorkspacesController#show)"
}

Datadog query for concurrent errors (같은 15분 창):

text
service:cupixworks-api status:error

결과: 같은 시간창의 error 로그는 전부 Cupix::PubSub::Subscribers::UserRecipeGeneratorprivate method 'service_jwt' called for class Cupix::NotificationService — 본 클러스터(#show 지연)와 별개의 이슈이며 500 응답을 유발하지도 않았다.

json
{
  "timestamp": "2026-07-16 14:34:26",
  "status": "error",
  "message": "processing 'facility_permission.full_permission_enabled' failed: private method `service_jwt' called for class Cupix::NotificationService",
  "class": "Cupix::PubSub::Subscribers::UserRecipeGenerator"
}

APM 메트릭 (p95:trace.rack.request{...resource_name:api::v1::workspacescontroller#show}, max:..., avg:trace.rack.request.duration.by.resource_service.by.http_status_code{...}) 은 시계열이 비어 반환 — 이 서비스에서 해당 metric name 이 발행되지 않는다. 따라서 baseline 대비 얼마나 튀었는지는 duration 로그가 아닌 APM 트레이스 뷰(Datadog URL) 로만 확인 가능. sample_trace_id 3044730468254276793 로도 로그 검색 결과 0 건 (trace 상세는 APM 콘솔에서만 조회).

확인되지 않은 정보 (needs verification)#

  • 문제 요청의 정확한 workspace_id, user_id, span breakdown — Datadog Logs API 만으로는 span-level 시간 분해를 얻을 수 없다. APM 콘솔의 3044730468254276793 트레이스 뷰에서 SQL/serialize/render 구간별 소요를 확인해야 한다.
  • 해당 요청 발생 순간의 tenant 별 workspace_permissions/team_permissions/grouped_users 카운트 및 lock 상태 — DB 로그/EXPLAIN 필요.
  • Rails 프로세스 GC pause 나 인접 요청의 write lock 대기 여부.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 permission_joins 6-LEFT-JOIN 쿼리의 tail latency outlier (cold plan / lock 대기 / 대형 permission 스캔) app/repositories/workspace_repository.rb:72-174 의 서브쿼리 구조; 같은 시간창의 다른 #show 는 정상 → permission_joins 의 tail 특성과 일치 span-level 증거 미확보 (APM 콘솔 필요) Confirmed (with note)
H2 상위 트래픽 급증으로 인한 systemic latency 클러스터 occurrence_count=1, 같은 분 다른 #show 는 정상 완료 시스템 전체 지연이었다면 occurrences 가 다수여야 함 Rejected
H3 동시간대 error 로그 (private method 'service_jwt') 가 원인 같은 서비스에서 다수 발생 이 에러는 Pub/Sub subscriber(비동기) 에서 발생하고 500 을 유발하지 않으며 #show 경로와 무관 Rejected
H4 외부 의존성(S3/ES 등) 장애 status-board 조회 시 active dep:* 인시던트 없음; error 로그도 dep 관련 아님 Rejected
H5 set_current_workspace (app/models/concerns/properties/user.rb:23-42) 의 Workspace.find + cache 갱신 지연 show 성공 후 호출됨; workspace 이미 로드된 상태이므로 추가 find 없음 (Workspace 인스턴스 branch) 정상 경로에서는 비용 낮음 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • 없음. 단일 occurrence 이고 200 정상 응답. 사용자 영향은 1건 세션의 11.4s 로딩 지연에 한정. 즉시 코드 변경은 불필요.
  • APM 콘솔에서 trace 3044730468254276793 를 열어 span 분해(예: SQL 쿼리 소요, ActiveRecord serialize, Elasticsearch 여부)를 확인하여 H1 을 span-level 로 최종 확정하는 것을 권장.

단기 개선 (1주 이내)#

  • Api::V1::WorkspacesController#show 에 대한 APM p95/p99 알림 임계값을 확인하고, 11s 급 outlier 가 반복되는지 24–48h 관찰. 반복 시 tenant/workspace_id 별 breakdown 으로 좁힘.
  • app/repositories/workspace_repository.rb:72-174 permission_joins 의 인덱스 존재를 EXPLAIN 으로 검증: workspace_permissions(accessor_id, accessor_type, workspace_id), team_permissions(accessor_id, accessor_type, team_id), grouped_users(group_id, user_id). 특히 LEFT JOIN 안쪽 서브쿼리는 index-only scan 이 되도록 covering index 여부 확인.

장기 개선 (재발 방지)#

  • permission_joins 는 단건 조회(show)에서도 index/list 조회와 동일한 6 서브쿼리를 실행한다. show 경로용으로 workspace_id 를 서브쿼리 안에 밀어 넣어 미리 필터링하는 특화 경로를 별도로 두는 것을 검토(현재는 .where(id: X) 가 outer 에서만 적용되어 permission 서브쿼리는 user 전체 permission 을 스캔).
  • APM trace sampling 이 낮다면 resource_name:Api::V1::WorkspacesController#show 에 대해 sampling rate 를 임시 상향해 outlier 재현 시 span-level 자료를 확보할 수 있게 설정.

Monitoring#

Timeseries 위젯용 Datadog 쿼리 (dashboard 에 그대로 삽입):

Api workspaces show p95 duration:

text
p95:trace.rails.request{service:cupixworks-api,resource_name:api::v1::workspacescontroller#show}

Api workspaces show p99 duration:

text
p99:trace.rails.request{service:cupixworks-api,resource_name:api::v1::workspacescontroller#show}

Slow request 발생률 (>5s):

text
sum:trace.rails.request.hits{service:cupixworks-api,resource_name:api::v1::workspacescontroller#show,duration:>5000000000}.as_count()

주의: 위 metric name (trace.rails.request) 은 서비스 계측 방식에 따라 다를 수 있어(trace.rack.request 실험 시 시계열 비어 반환) dashboard 반영 전에 Datadog Metrics Explorer 에서 trace. prefix 를 실제 발행되는 이름으로 확인 필요 — needs verification.

Risk Assessment#

  • Risk level: low (단일 occurrence, 정상 200 응답, 즉시 사용자 영향 미미)
  • 예상 복잡도: standard (즉시 코드 fix 불필요, APM trace 후속 검증 + monitoring 튜닝 위주)