RCA: Api::V1::AnnotationLayersController#create Latency (avg 2602ms, max 4216ms)

Overview#

What Happened#

2026-05-27 08:15~08:16 UTC에 cupixworks-api 서비스의 Api::V1::AnnotationLayersController#create 엔드포인트에서 평균 2602ms, 최대 4216ms의 응답 지연이 발생했다. 단일 사용자(User 751)가 여러 facility에 걸쳐 AnnotationLayer를 연속 생성하는 배치 작업 중 발생했으며, 첫 번째 요청이 가장 느리고 이후 점차 빨라지는 패턴을 보였다.

Quick Facts#

Timeline#

1. 08:15:07Z — 첫 번째 느린 요청 감지 (4214ms)
2. 08:15:11Z — Duplicate permission 경고 8건 발생
3. 08:15:45Z — 두 번째 요청 (2090ms)
4. 08:16:10Z — 세 번째 요청 (1494ms)
5. 08:17:00Z~ — 이후 요청 정상화 (700~900ms대)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::AnnotationLayersController#create",
  "service": "cupixworks-api",
  "occurrences": 3,
  "avg_ms": 2602,
  "max_ms": 4216,
  "sample_trace_id": "40131777910111686"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 3
• 최초 발생: 2026-05-27T08:15:07.685Z
• 최근 발생: 2026-05-27T08:16:10.625Z
• 영향 범위: 단일 사용자(User 751)의 배치 생성 작업에만 영향. 데이터 손실 없음, 모든 요청 HTTP 200 성공.

Root Cause Summary#

AnnotationLayersController#create의 응답 지연은 데이터베이스 쿼리(30~38ms)가 아닌 동기적 after_create/after_commit 콜백 체인에서 발생했다. 총 요청 시간 중 ~98%가 애플리케이션 레벨 콜백에서 소비되었으며, 핵심 병목은 세 가지다:

1. 동기적 Elasticsearch 인덱싱 (Searchable concern의 after_commit): HTTP 호출로 Elasticsearch에 문서를 인덱싱
2. 동기적 AWS Kinesis 이벤트 발행 (Eventable::Callbacks의 after_create): Kinesis put_records! 호출
3. ObjectSpace.each_object(Class) 스캔 (EntityUpdates::Child의 after_create): 모든 로드된 클래스를 순회하여 parent 클래스를 찾는 비용이 큰 연산

첫 번째 요청이 가장 느린 이유는 cold-start 시 Elasticsearch 커넥션 풀 초기화와 Kinesis 클라이언트 초기화가 추가 지연을 유발했기 때문이다. 이후 요청에서는 이미 warmed-up된 커넥션을 재사용하여 점차 빨라졌다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/annotation_layers_controller.rb:27
• Factory: app/factories/annotation_layer_factory.rb:5 (create!)
• Model save: app/factories/base_factory.rb:80-141
• Failure point (latency): 동기 콜백 체인 (after_create + after_commit)

1. Controller create action:

def create
  @model = factory_instance.create!(params)

  super
end

2. Factory에서 FacilityRepository.show로 facility 조회 후 model.save! 호출:

def create!(params = {})
  self.model = ::AnnotationLayer.new

  if params[:facility_key].present?
    self.parent = FacilityRepository.new(current_user: self.current_user).show(params[:facility_key])
    self.model.facility = self.parent
  elsif params[:facility].present?
    self.parent = FacilityRepository.new(current_user: self.current_user).show(params[:facility].key)
    self.model.facility = self.parent
  end
  # ... super -> model.save!
end

3. after_create: 동기적 Kinesis 이벤트 발행 (주요 병목 #1):

def self.publish_event(events = [])
  return if events.blank?
  return if %w[development test].include?(Rails.env)

  records = events.map do |event|
    { data: event.serializable_hash.to_json, partition_key: Current.request_id || SecureRandom.uuid }
  end

  stream_name = "#{::Cupix::Tesla.tenant}-cupixworks-#{Rails.env}-EventStream"
  response = Cupix::Aws::Kinesis.put_records!({ stream_name: stream_name, records: records })
  # 동기 호출 — 응답 대기 시간이 요청 duration에 포함됨
end

4. after_create: ObjectSpace 스캔으로 parent 클래스 탐색 (주요 병목 #2):

class << self
  def parent_classes
    Cupix::Loader.load

    ObjectSpace.each_object(Class).select do |model|
      model.superclass == ApplicationRecord && !model.name.include?('::') && !model.name.ends_with?('Permission') && model.respond_to?(:entities) && model.entities.include?(self.name.underscore.to_sym)
    end.map(&:name)
  end
end

5. after_commit: 동기적 Elasticsearch 인덱싱 (주요 병목 #3):

def _index_document
  return if @skip_index_document == true

  indexed_json = __elasticsearch__.as_indexed_json
  base_request = {
    id: __elasticsearch__.id,
    body: indexed_json
  }

  results = __elasticsearch__.client.index(base_request.merge(index: __elasticsearch__.index_name))

  if (tmp_index = self.class.fetch_tmp_index_name)
    __elasticsearch__.client.index(base_request.merge(index: tmp_index))
  end
rescue StandardError => e
  Cupix::Logger.error("Index error - #{e.message}", class: self.class.name, function: __method__)
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

6. after_create: Permission 생성 + 캐시 flush (추가 지연):

after_create :share_to_creator, unless: :share_to_creator_skip?

def share_to_creator
  return nil if self.user.nil?
  self.share!(self.user, permission_for_creator)
end

share! → add_permission!에서 flush_cached_permissions 호출 시 동기적으로 사용자 캐시를 삭제한다.

Log Evidence#

Datadog 검색 쿼리:

service:cupixworks-api @http.url_details.path:*/annotation_layers* @http.method:POST env:production

요청 duration vs DB time 비교 (incident window):

08:15:12Z | duration: 4214ms | db: 32ms | host: ip-10-1-144-228
08:15:46Z | duration: 2090ms | db: 37ms | host: ip-10-1-80-134
08:16:12Z | duration: 1494ms | db: 35ms | host: ip-10-1-144-228

DB 시간은 모든 요청에서 30~38ms로 일정하며, 총 요청 시간과의 차이(~4180ms at peak)는 전부 애플리케이션 콜백에서 소비되었다.

Duplicate permission 경고 (incident 시작점과 정확히 일치):

service:cupixworks-api status:warn

{
  "message": "[Permission] Duplicate permission detected, retrying for User(23194) on Facility(16478)",
  "timestamp": "2026-05-27T08:15:11Z",
  "class": "Facility",
  "function": "add_permission!"
}

08:15:11~13Z 사이에 8건의 duplicate permission 경고가 발생하여 가장 느린 첫 번째 요청(4214ms)과 시간적으로 겹친다. 이는 Permissionable#add_permission!에서 RecordNotUnique 예외 발생 후 retry 하는 과정에서 추가 지연이 발생했음을 시사한다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/searchable.rb:12-14 — after_commit on: [:create]에서 _index_document를 비동기 Sidekiq worker로 변경. 현재 rescue 절에서 이미 BulkIndexWorker로 fallback 하고 있으므로, 기본 경로를 worker로 전환하면 된다.
• lib/cupix/event_service.rb:43 — Cupix::Aws::Kinesis.put_records! 호출을 비동기 worker로 전환하여 요청 응답 경로에서 분리.

단기 개선 (1주 이내)#

• app/models/concerns/entity_updates/child.rb:15-17 — ObjectSpace.each_object(Class) 결과를 클래스 레벨에서 캐싱. parent_classes는 런타임에 변하지 않으므로 @@parent_classes ||= ... 패턴으로 한 번만 계산하면 된다.
• app/models/concerns/permissionable.rb:60-71 — flush_cached_permissions 호출을 FlushCachedPermissionWorker.perform_async로 전환 (instance method에서는 이미 worker를 사용하지만, class method에서는 동기 호출).

장기 개선 (재발 방지)#

• AnnotationLayer 생성 시 실행되는 콜백 수가 과도함 (Eventable, Searchable, EntityUpdates, Permissionable, Positionable, DataWareHouse 등). 콜백을 감사(audit)하여 요청 경로에서 필수적인 것만 동기로 유지하고, 나머지는 모두 비동기(Sidekiq)로 분리하는 아키텍처 리팩터링 권장.
• APM에 custom span을 추가하여 각 콜백의 소요 시간을 개별 측정할 수 있도록 계측(instrumentation) 추가.

Monitoring#

• Datadog APM에서 AnnotationLayersController#create p95 duration 모니터링 추가
• 임계치: p95 > 1000ms 시 alert

avg(last_5m):trace.rack.request{service:cupixworks-api, resource_name:Api::V1::AnnotationLayersController#create} > 1000

• Elasticsearch indexing 실패(BulkIndexWorker fallback) 빈도 모니터링
• Kinesis put_records failed_record_count 메트릭 추가

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard
• 데이터 손실 없음, 모든 요청 성공 (HTTP 200). 사용자 체감 지연만 존재. 단일 사용자 배치 작업에서만 발현되었으며, 일반적 단건 생성에서는 재현 가능성 낮음.