RCA: Api::V1::AnnotationsController#show latency (avg 309s / max 309s)

Overview#

What Happened#

2026-07-21 19:16 KST 무렵 cupixworks-api의 eu-central-1 리전에서 GET /api/v1/reviews/:review_key/annotations/:id 요청이 약 309초(≈5분 9초) 동안 지속된 하나의 APM span이 관측되었다. 동일 시간대에 완료 로그([200] ... AnnotationsController#show)가 남아 있지 않아, 업스트림(ALB/Puma) timeout 이 걸린 뒤 span 만 close 된 이례적 요청이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-21 19:11 KST 무렵 — Span 시작 (10:16:58 UTC − 309s ≈ 10:11:49 UTC = 19:11:49 KST). Datadog log 에도 대응되는 request-start 로그가 없다 — Rails/Rack request logger 는 finish 시점에 방출되므로 예상되는 결과다.
2. 2026-07-21 19:11 ~ 19:18 KST — 같은 eu-central-1 리전에서 AnnotationsController#index 요청이 짧은 시간에 다수 발생 (Datadog 로그로 최소 20+ 건 확인). 부하 spike 국면.
3. 2026-07-21 19:16:58 KST — 문제의 #show span 종료 (duration 309,016 ms). 완료 로그([200] GET /api/v1/reviews/emlkv5/annotations/... (Api::V1::AnnotationsController#show)) 는 이 timestamp 에 존재하지 않는다.
4. 2026-07-21 19:17:15 KST — 정상 #show 응답 재개 (/reviews/emlkv5/annotations/12297, 200 OK).

Error Log#

Datadog Logs

resource_name: Api::V1::AnnotationsController#show
service:       cupixworks-api
occurrences:   1
avg_ms:        309016
max_ms:        309016
sample_trace_id: 1147796689992067536

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-21 19:16 KST
• 최근 발생: 2026-07-21 19:16 KST
• Region: eu-central-1

Root Cause Summary#

Api::V1::AnnotationsController#show 는 set_annotation before_action 에서 AnnotationRepository#show → BaseRepository.show 를 호출하는데, 이 경로가 permission_joins(default_joins(current_class)) 로 감싸진 매우 무거운 SQL 을 실행한다. permission_joins 는 리뷰/annotation/annotation_layer/facility/workspace/team 각각에 대해 user & group 서브쿼리 총 14 개의 LEFT JOIN 을 만들고 MAX(...) aggregation 을 위해 GROUP BY id 를 강제한다 (app/repositories/annotation_repository.rb:80-305). 단일 레코드 조회에도 이 heavy join 이 붙어 있어, annotations/permission 테이블이 크거나 permission_joins subquery 가 index 를 효과적으로 못 쓰는 상황에서 쿼리 시간이 초 단위 이상으로 늘어난다. 문제 시점에 eu-central-1 에서 AnnotationsController#index 트래픽이 spike 하여 DB connection/CPU 경합이 발생했고, 그 사이 실행된 이 #show 요청이 약 309초 동안 blocking 되어 upstream timeout 에 도달했다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/annotations_controller.rb:12

before_action :set_review, if: :require_review?
before_action :set_annotation, except: %i[create index search untrash purge mock bulk_share bulk_unshare bulk_trash index_by_badge_ids index_by_asset]

include MultipleResourcableController

#show action 자체는 Api::V1::ApiController#show 에서 상속되어 @model 을 그대로 render 한다 — 무거운 작업은 전부 before_action 단계에서 발생한다:

def show
  render_api Renderable.new({
    contents: @model,
    serializer_option: @serializer_option
  })
end

set_annotation 은 AnnotationRepository#show 를 호출:

def set_annotation
  @model = repository_instance.show(params[:id])
end

BaseRepository#show (instance) → self.class.show (class-level):

def show(id, visibility: Cyclable.visibility[:UNTRASHED], review_id: nil, capture_id: nil, skip_permission: false)
  _review_id = if review_id.present?
                 review_id
               elsif self.review.present?
                 self.review.id
               end

  @model = self.class.show(id, current_user: @current_user, visibility: visibility, review_id: _review_id, capture_id: capture_id, skip_permission: skip_permission)
end

Failure point — BaseRepository.show 는 current_user 있으면 무조건 permission_joins 를 붙인다:

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

AnnotationRepository.permission_joins 실체 (요약):

def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  # ...
  record.joins("
    LEFT JOIN (...) AS review_user_permissions ...
    LEFT JOIN (...) AS review_group_permissions ...
    LEFT JOIN (...) AS annotation_user_permissions ...
    LEFT JOIN (...) AS annotation_group_permissions ...
    LEFT JOIN (...) AS annotation_layer_user_permissions ...
    LEFT JOIN (...) AS annotation_layer_group_permissions ...
    LEFT JOIN (...) AS facility_user_permissions ...
    LEFT JOIN (...) AS facility_group_permissions ...
    LEFT JOIN (...) AS facility_system_group_permissions ...
    LEFT JOIN (...) AS workspace_user_permissions ...
    LEFT JOIN (...) AS workspace_group_permissions ...
    LEFT JOIN (...) AS team_user_permissions ...
    LEFT JOIN (...) AS team_group_permissions ...
    LEFT JOIN (...) AS team_system_group_permissions ...
  ").group('id').select(_select).where("...GREATEST(IFNULL(...)) filters...")
end

default_joins 도 annotations × captures LEFT OUTER JOIN 및 storage/facility/form_design include 를 겹쳐 붙인다:

def self.default_joins(record)
  record.includes(:storage).left_outer_joins(:facility, :form_design).joins("
    LEFT OUTER JOIN captures ON annotations.annotatable_id = captures.id AND annotations.annotatable_type = 'CAPTURE'
  ").select("
    annotations.*,
    form_designs.description AS form_design_description,
    form_designs.name AS form_design_name,
    form_designs.icon as form_design_icon,
    facilities.cycle_state AS applied_cycle_state
  ").where("captures.trashed_at": nil)
end

기대 동작: annotations.id = ? 조건이 확실히 지정되므로 primary key index scan 후 permission 검사만 O(1)에 가깝게 수행되어 100ms 이내에 반환되어야 한다.

실제 동작: permission_joins 서브쿼리가 annotations.id = ? filter 를 outer query 밖에서 걸어도 각 서브쿼리는 permission 테이블 전체를 스캔 후 join 하기 때문에, permission 테이블(팀 규모에 따라 수십만 row)이 크거나 index 가 부족하면 실행 계획이 nested loop → hash join → group-by 로 폭발한다. 여기에 #index 트래픽이 같은 DB 인스턴스에서 동시에 실행되면 buffer pool/connection 이 경합해 대기 시간이 초 단위로 축적된다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api region:eu-central-1 "AnnotationsController#show"

service:cupixworks-api region:eu-central-1 @trace_id:1147796689992067536

service:cupixworks-api region:eu-central-1 "annotations/"
  (time: 2026-07-21T10:10:00Z ~ 2026-07-21T10:20:00Z)

핵심 관측:

1. Sample trace 1147796689992067536 에 대한 완료 로그가 존재하지 않는다 (@trace_id 검색 0건). Rails/Rack request logger 는 응답이 flush 될 때만 로그를 남기므로, upstream 이 request 를 abort 했거나 client 가 close 했을 가능성이 크다.

2. 동일 리전에서 문제 시점 직후 몇 초 사이 #index 응답이 대량으로 쏟아진다 — 부하 spike 정황:

2026-07-21 19:18:07  info  [200] GET /api/v1/reviews/emlkv5/annotations (Api::V1::AnnotationsController#index)
2026-07-21 19:18:07  info  [200] GET /api/v1/reviews/emlkv5/annotations (Api::V1::AnnotationsController#index)
2026-07-21 19:18:07  info  [200] GET /api/v1/reviews/emlkv5/annotations (Api::V1::AnnotationsController#index)
2026-07-21 19:18:05  info  [200] GET /api/v1/reviews/emlkv5/annotations (Api::V1::AnnotationsController#index)
2026-07-21 19:18:05  info  [200] GET /api/v1/reviews/emlkv5/annotations (Api::V1::AnnotationsController#index)
...  (10+ 건이 2초 window 안에)

3. #show 정상 응답은 19:16:58 KST 이후 최초로 19:17:15 KST 에 관측되었다 (다른 annotation id):

2026-07-21 19:17:15  info  [200] GET /api/v1/reviews/emlkv5/annotations/12297 (Api::V1::AnnotationsController#show)

4. 동일 리전에서 문제 시점(2026-07-21T10:10~10:20Z)에 status:error 또는 status:warn 로그는 0건. 즉 예외 발생이 아니라 순수 latency 이슈다:

service:cupixworks-api region:eu-central-1 (status:error OR status:warn)
  → Found 0 logs

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 트래픽 완화 (운영 대응): eu-central-1 리전에서 AnnotationsController#index 가 짧은 시간에 다수 호출되는 패턴을 프런트엔드/클라이언트와 확인. #index 를 반복 호출하며 사이사이 #show 가 끼는 UX 흐름이라면 클라이언트 debounce/캐시 도입은 프런트 조율이 필요하므로 자동 code-fix 범위에서 제외 — 별도 트랙으로 관리.
• BaseRepository.show 의 permission_joins fast-path 도입 검토 — app/repositories/base_repository.rb:331-343. 단일 id 로 조회할 때는 permission 검사를 별도의 lightweight 쿼리(예: where(annotations: { id: attrs[:id] }) 로 permission subquery 를 프리 필터링)로 분리하거나, first 로 fetch 한 후 Pundit.policy(current_user, model).read? 만으로 판정하도록 재설계.
• Slow-query 알림 확인: MySQL slow_query_log / RDS Performance Insights 에서 2026-07-21 10:11~10:17 UTC 사이 annotations 관련 top-N 쿼리를 확보해 실제 실행 계획을 검증.

단기 개선 (1주 이내)#

• AnnotationRepository.permission_joins 서브쿼리 각각에 WHERE annotation_id = <bound> prefilter 추가: 현재 서브쿼리는 WHERE ... = current_user.id 만 걸고 permission 테이블 전체를 join 재료로 만든 뒤 outer 에서 filter 한다. Outer 에서 annotations.id = ? 가 이미 정해져 있을 때 서브쿼리에도 AND permission.annotation_id = ? 형태의 push-down 을 걸면 매 서브쿼리의 row 수를 대폭 줄일 수 있다. 단일 id 경로에 한해 별도 오버로드 제공을 고려.
• GROUP BY id 제거 가능성 검토: 단일 record fetch 는 MAX(...) 대신 permission 존재 여부만 판정하면 되므로 EXISTS 서브쿼리로 재작성 가능한지 스터디.
• Puma worker/DB pool 튜닝: eu-central-1 인스턴스 크기 및 pool size 대비 요청 burst 대응 여유가 있는지 재확인.

장기 개선 (재발 방지)#

• Permission model refactor: 리소스 × accessor × group 조합의 서브쿼리 폭발을 막기 위해 flatten 된 permission cache 테이블 도입 (예: effective_annotation_permissions(user_id, annotation_id, permission)).
• APM latency SLO / alarm: Api::V1::AnnotationsController#show p95 가 500ms 를 초과하는 경우 자동 알림. 현재 avg 309s max 309s 라는 outlier 가 발생해도 error 로그가 없어 감지 지연.
• Region-level 트래픽 분석 자동화: #index burst 감지 시 자동으로 caller 정보를 수집하는 dashboard/monitor 추가.

Monitoring#

Datadog 쿼리 (release dashboard timeseries widget 용, writing-datadog-monitoring-queries 가이드 준수):

• p95 latency of #show by region:

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::annotationscontroller#show} by {region}

• Request count of #show (baseline 파악):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::annotationscontroller#show} by {region}.as_rate()

• #index burst 검출:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::annotationscontroller#index,region:eu-central-1}.as_rate()

• DB latency (annotations 관련 쿼리 감지):

avg:mysql.performance.query_run_time_avg{service:cupixworks-api,region:eu-central-1}

Risk Assessment#

• Risk level: medium — 현재 1회 관측이지만 permission_joins 구조 자체가 부하 spike 상황에서 recurrent latency 를 일으킬 잠재력이 크다. 사용자 impact 는 단발성 5분 응답 실패로 제한적이었다.
• 예상 복잡도: standard — 즉시 조치(운영 관찰)와 단기 개선(SQL push-down 재작성)은 표준 작업. 장기 개선(permission cache 도입)은 별도 프로젝트 규모.