ES /docs

Api::V1::AnnotationsController#create (avg 2281ms, max 3421ms)

RCA: Api::V1::AnnotationsController#create Latency (avg 2281ms, max 3421ms)

Overview#

What Happened#

2026-05-26 08:28~12:10 UTC 사이에 eu-central-1 리전의 cupixworks-api 서비스에서 AnnotationsController#create 요청이 평균 2281ms, 최대 3421ms의 응답 시간을 기록했다. 전체 요청 시간의 75-82%가 DB 쿼리 시간이며, 특정 review(zao9w4, ubdy79)에서 가장 심각한 지연이 발생했다. 모든 요청은 HTTP 200으로 성공 응답했으나, 사용자 체감 성능이 크게 저하되었다.

Quick Facts#

Field Value
resource_name Api::V1::AnnotationsController#create
top_frame app/repositories/annotation_layer_repository.rb:62-258 (permission_joins)
env production, eu-central-1
avg_duration 2281ms
max_duration 3421ms (review zao9w4), 4825ms (review ubdy79 outlier)

Affected Teams#

Team / Domain Error Count Impact
repsol (team_id: 102) 6+ (50+ slow requests total) Annotation 생성 시 2-5초 대기, 사용자 생산성 저하

Timeline#

  1. 2026-05-26 08:28 UTC — 최초 slow request 감지 (1763ms, review emlkv5)
  2. 2026-05-26 08:51 UTC — 최악의 케이스 발생 (4825ms, review ubdy79)
  3. 2026-05-26 12:10 UTC — 마지막 감지된 slow request (1935ms)
  4. 2026-05-26 — RCA 분석 수행

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::AnnotationsController#create",
  "service": "cupixworks-api",
  "occurrences": 6,
  "avg_ms": 2281,
  "max_ms": 3421,
  "sample_trace_id": "993609889660661642"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 6 (threshold 초과 건수), 실제 >1000ms slow request 50건
  • 최초 발생: 2026-05-26T08:28:04.707Z
  • 최근 발생: 2026-05-26T12:10:00.422Z

Root Cause Summary#

AnnotationsController#create의 latency는 AnnotationLayerRepository.permission_joins에서 수행되는 12개 LEFT JOIN을 포함한 복합 permission 쿼리가 원인이다. Annotation 생성 시 AnnotationLayerRepository.show()가 두 번 호출되어(factory에서 1회, set_parameters에서 1회) 동일한 heavy permission query가 중복 실행된다. 특히 repsol 팀(team_id: 102)의 review zao9w4, ubdy79는 permission 테이블의 데이터가 많아 JOIN 비용이 높으며, DB 시간이 전체 요청 시간의 75-82%를 차지한다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/annotations_controller.rb:27
  • Factory 호출: app/factories/annotation_factory.rb:12 — 첫 번째 AnnotationLayerRepository.show() 호출
  • Parameter 설정: app/concerns/parameter/annotation.rb:18 — 두 번째 AnnotationLayerRepository.show() 호출 (중복)
  • Permission 쿼리 실행: app/repositories/base_repository.rb:337app/repositories/annotation_layer_repository.rb:62-258
  • Event 생성: app/models/concerns/eventable/callbacks.rb:31after_create 콜백에서 Event INSERT

1단계: Controller → Factory

app/controllers/api/v1/annotations_controller.rb:27-31ruby
def create
  @model = factory_instance.create!(params)

  super
end

2단계: Factory에서 AnnotationLayer를 permission_joins로 조회 (1차)

app/factories/annotation_factory.rb:11-12ruby
self.model = ::Annotation.new
self.model.annotation_layer = AnnotationLayerRepository.new(current_user: self.current_user, review: review).show(params[:annotation_layer_id])

3단계: set_parameters에서 동일한 AnnotationLayer를 다시 조회 (2차 — 중복)

app/concerns/parameter/annotation.rb:17-19ruby
if params[:annotation_layer_id].present?
  annotation_layer = AnnotationLayerRepository.new(current_user: current_user, review: self.review).show(params[:annotation_layer_id])
  @model.annotation_layer = annotation_layer
end

annotation_layer_idcreate!에서 required parameter이므로 항상 present하며, 따라서 set_parameters에서도 항상 조회가 실행된다.

4단계: permission_joins — 12개 LEFT JOIN 포함 복합 쿼리

app/repositories/annotation_layer_repository.rb:62-93ruby
def self.permission_joins(record, current_user, select: nil, review_id: -1, **kwargs)
  if select.present?
    _select = ApplicationRecord.sanitize_sql(select)
  else
    _select = "annotation_layers.*,
    MAX(review_user_permissions.permission) AS review_user_permission,
    MAX(review_group_permissions.permission) AS review_group_permission,
    MAX(annotation_layer_user_permissions.permission) AS annotation_layer_user_permission,
    MAX(annotation_layer_group_permissions.permission) AS annotation_layer_group_permission,
    MAX(facility_user_permissions.permission) AS facility_user_permission,
    MAX(facility_group_permissions.permission) AS facility_group_permission,
    MAX(facility_system_group_permissions.permission) AS facility_system_group_permission,
    MAX(workspace_user_permissions.permission) AS workspace_user_permission,
    MAX(workspace_group_permissions.permission) AS workspace_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(GREATEST(
      IFNULL(annotation_layer_user_permissions.permission, 0),
      ...
    )) AS applied_permission"
  end
app/repositories/base_repository.rb:336-337ruby
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)

이 쿼리는 review_permissions, annotation_layer_permissions, facility_permissions, workspace_permissions, team_permissions, grouped_users 테이블을 각각 user/group 별로 LEFT JOIN하여 총 12개의 서브쿼리를 조합한다. repsol 팀처럼 permission 엔트리가 많은 경우 쿼리 비용이 급격히 증가한다.

Log Evidence#

Datadog에서 확인한 slow request 패턴:

text
service:cupixworks-api resource_name:"Api::V1::AnnotationsController#create" @duration:>500ms env:production

대표적인 slow request 로그:

json
{
  "timestamp": "2026-05-26T08:51:23.188Z",
  "duration_ms": 4825,
  "db_ms": 3959,
  "path": "/api/v1/reviews/ubdy79/annotations",
  "host": "ip-10-1-147-251",
  "request_id": "4ac619ab-75a1-4770-99c6-94bc031209d3",
  "user": "adnande.chahboun@servexternos.repsol.com",
  "status": 200
}
json
{
  "timestamp": "2026-05-26T09:50:42.694Z",
  "duration_ms": 3419,
  "db_ms": 2486,
  "path": "/api/v1/reviews/zao9w4/annotations",
  "host": "ip-10-1-82-161",
  "request_id": "72128da0-b192-4ce5-b4b1-83ca34d7dbb7",
  "user": "cristian.mendoza@servexternos.repsol.com",
  "status": 200
}

DB 시간 비율 분석:

  • review ubdy79: 3959ms / 4825ms = 82% DB
  • review zao9w4: 2486ms / 3419ms = 73% DB
  • review emlkv5: 1383ms / 1763ms = 78% DB

모든 케이스에서 DB 시간이 전체의 73-82%를 차지하며, 호스트(ip-10-1-147-251, ip-10-1-82-161) 무관하게 동일한 패턴이 발생한다. 이는 특정 인스턴스의 문제가 아닌 쿼리 자체의 비용 문제임을 확인한다.

에러 로그 부재: Annotation 생성과 관련된 error/warn 로그는 없었으며, 모든 요청이 HTTP 200으로 완료되었다. 이는 기능적 장애가 아닌 순수 성능 문제임을 확인한다.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 permission_joins 12-LEFT-JOIN 쿼리의 중복 실행이 latency 원인 DB 시간 73-82% 차지, AnnotationLayerRepository.show() 2회 호출 확인 (annotation_factory.rb:12, parameter/annotation.rb:18), 모든 호스트에서 동일 패턴 Confirmed
H2 DB connection pool 고갈 또는 connection timeout 여러 호스트에서 동시 발생 가능 error/warn 로그 없음, connection timeout/pool 관련 에러 0건, 모든 요청 성공 Rejected
H3 Elasticsearch 병목 (annotation layer 검색) AnnotationLayerRepository가 ES search 사용 가능 show()는 ES가 아닌 permission_joins SQL 쿼리 사용 (base_repository.rb:337), ES 에러 0건 Rejected
H4 after_create EventFactory의 동기 INSERT 추가 비용 eventable/callbacks.rb:31에서 Event 레코드 생성 Event INSERT는 단일 테이블 INSERT로 비용이 낮음, DB 시간의 대부분은 SELECT permission 쿼리에 소요 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • app/concerns/parameter/annotation.rb:17-19에서 annotation_layer_id에 대한 중복 조회 제거. AnnotationFactory#create!에서 이미 @model.annotation_layer를 설정하므로, set_parameters에서는 @model.annotation_layer가 nil인 경우에만 조회하도록 조건 변경.
  • 이 변경만으로 permission_joins 쿼리 1회 제거 — 예상 latency 40-50% 감소.

단기 개선 (1주 이내)#

  • AnnotationLayerRepository.permission_joins 쿼리 최적화: repsol 팀처럼 permission 엔트리가 많은 경우를 위해, permission 테이블에 복합 인덱스 추가 (accessor_id, accessor_type 조합).
  • BaseRepository.show() 결과를 request 스코프에서 캐싱하는 메커니즘 도입 (예: RequestStore gem 활용), 동일 request 내 동일 ID 조회 시 DB 쿼리 재실행 방지.

장기 개선 (재발 방지)#

  • Permission 확인 로직을 materialized view 또는 캐시 레이어로 분리. 현재 12개 LEFT JOIN은 permission 구조가 확장될수록 성능이 선형적으로 저하된다.
  • 권한 변경 시 비동기로 permission 결과를 갱신하는 이벤트 기반 캐시 도입 검토.

Monitoring#

  • AnnotationsController#create p95/p99 latency 모니터 추가
  • DB 시간 비율이 80% 이상인 요청에 대한 알림 설정
text
service:cupixworks-api resource_name:"Api::V1::AnnotationsController#create" @duration:>2000ms env:production

Risk Assessment#

  • Risk level: medium
  • 예상 복잡도: standard (중복 호출 제거는 trivial, permission 쿼리 최적화는 standard)