Api::V1::CapturesController#create (avg 2072ms, max 5065ms)

RCA: CapturesController#create Latency (avg 2072ms, max 5065ms)

Overview#

What Happened#

2026-05-26 03:34~06:17 UTC 동안 cupixworks-api 서비스의 Api::V1::CapturesController#create 엔드포인트에서 평균 2072ms, 최대 5065ms(실제 샘플에서 최대 10546ms)의 응답 지연이 30건 발생했다. ap-southeast-2와 us-west-2 리전에서 모두 발생했으며, 특히 ap-southeast-2 리전에서 심각했다.

Quick Facts#

Field	Value
resource_name	`Api::V1::CapturesController#create`
top_frame	`app/controllers/api/v1/captures_controller.rb:40`
avg_duration	2072ms (cluster) / 1604ms (sampled 50)
max_duration	5065ms (cluster) / 10546ms (sampled)
env	production, us-west-2 + ap-southeast-2

Affected Teams#

Team / Domain	Error Count	Impact
endeavourgroup	4	평균 4792ms, 최대 10546ms — 캡처 생성 극심한 지연
hawkins	4	평균 2343ms — 캡처 업로드 시작 지연
unispace	1	3523ms — 개별 요청 지연
built	1	6952ms — 캡처 생성 지연

Timeline#

2026-05-26T02:55:05Z — 최초 고지연 요청 발생 (10546ms, endeavourgroup)
2026-05-26T03:34:35Z — 클러스터 최초 감지 시점
2026-05-26T06:17:47Z — 마지막 발생
2026-05-26 — RCA 수행

Error Log#

Datadog Logs

json

{
  "resource_name": "Api::V1::CapturesController#create",
  "service": "cupixworks-api",
  "occurrences": 30,
  "avg_ms": 2072,
  "max_ms": 5065,
  "sample_trace_id": "675175679782530871"
}

Impact#

Service: cupixworks-api
발생 횟수: 30
최초 발생: 2026-05-26T03:34:35.599Z
최근 발생: 2026-05-26T06:17:47.575Z
영향 리전: ap-southeast-2 (평균 1924ms), us-west-2 (평균 1034ms)
사용자 영향: 캡처 업로드 시작이 수 초간 블로킹되어 클라이언트(모바일 앱, 웹) 사용성 저하

Root Cause Summary#

CapturesController#create 요청 처리 중 FacilityPermission 생성 시 PubSub::Publisher의 after_commit 콜백이 UserRecipeGenerator와 SubscriptionGenerator subscriber를 동기적으로 실행하여 Cupix::NotificationService에 대해 최대 4회의 HTTP 호출(3x create_user_recipe + 1x subscribe)을 순차적으로 수행한다. 각 호출이 ~~2초 소요되어, 새로운 facility permission이 생성되는 케이스에서 총 8~~10초의 지연이 발생한다. DB 쿼리 시간은 35~171ms로 정상 범위이며, 지연의 핵심은 notification-service로의 동기 HTTP 호출이다.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/captures_controller.rb:40

app/controllers/api/v1/captures_controller.rb:40-43ruby

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

CaptureFactory가 RecordFactory를 호출하여 Record를 찾거나 생성:

app/factories/capture_factory.rb:27-30ruby

elsif params[:captured_at].present?
  raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'facility key is required when using captured_at') if self.model.facility.nil?
  self.parent = RecordFactory.new(current_user: self.current_user).find_or_create_by_captured_at!(facility: self.model.facility, captured_at: params[:captured_at])
end

BaseFactory에서 model.save! 호출:

app/factories/base_factory.rb:123-125ruby

begin
  self.model.save!
  self.model

Capture.save! 후 after_commit 에서 Elasticsearch 인덱싱 실행 (Searchable concern):

app/models/concerns/searchable.rb:12-13ruby

after_commit on: [:create] do
  _index_document
end

app/models/concerns/searchable.rb:34-49ruby

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
end

핵심 지연 지점: FacilityPermission 생성 시 PubSub after_commit 콜백에서 NotificationService 동기 호출:

app/models/concerns/pub_sub/publisher.rb:29-44ruby

after_create do |model|
  model.pub_sub_notifications_manager.add_notification(namespace, 'created', { model: model })
end

after_commit do |model|
  model.pub_sub_notifications_manager.publish_notifications(namespace)
  model.pub_sub_notifications_manager.reset_notifications(namespace)
end

UserRecipeGenerator subscriber가 created 이벤트를 수신하면 3개의 HTTP POST 요청을 순차 실행:

lib/cupix/pub_sub/subscribers/user_recipe_generator.rb:34-41ruby

def _create_recipes(opts = {})
  %w[
    record_preview_ready
    record_processing_completed
    facility_new_project
  ].each do |recipe_name|
    Cupix::NotificationService.new(user: opts[:user]).create_user_recipe(recipe_name, team_id: opts[:team_id], facility_key: opts[:facility_key])
  end
end

SubscriptionGenerator subscriber도 동기적으로 subscribe 호출:

lib/cupix/pub_sub/subscribers/subscription_generator.rb:20-21ruby

def _create_subscription(opts = {})
  Cupix::NotificationService.new(user: opts[:user]).subscribe(facility_key: opts[:facility_key])
end

NotificationService의 모든 HTTP 호출은 동기적/블로킹 (RestClient 사용):

lib/cupix/notification_service.rb:15-22ruby

response = Cupix::HttpClient.post(
  "#{@service_url}/api/recipes/v2",
  params.to_json,
  {
    content_type: :json,
    'x-cupix-auth': @user.api_token
  }
)

HttpClient는 실패 시 exponential backoff로 최대 3회 재시도 (429/502/503/504):

lib/cupix/http_client.rb:34-46ruby

def self.post(url, payload, headers = {}, retries: MAX_RETRIES)
  attempt = 0
  begin
    RestClient.post(url, payload, headers)
  rescue RestClient::Exception => e
    if RETRIABLE_STATUS_CODES.include?(e.http_code) && attempt < retries
      attempt += 1
      sleep((2**(attempt - 1)) + rand(0.0..0.5))
      retry
    end
    raise
  end
end

Log Evidence#

Datadog에서 가장 느린 요청(10546ms)의 trace 타임라인을 분석한 결과:

text

Datadog query: service:cupixworks-api resource_name:"Api::V1::CapturesController#create" env:production @duration:>500ms
Time window: 2026-05-26T02:34:35Z to 2026-05-26T06:17:47Z

최고 지연 요청의 시간 분해 (request ID: bee47553-d8b2-4e7c-8a39-e9fe1de4507f):

text

02:54:54.899 - RecordFactory creates Record, invalidates facility review caches
02:54:56.901 (+2.0s) - Capture created (ID 73254), state transition, permission flush, cache invalidation
02:55:00.904 (+4.0s) - NotificationService.create_user_recipe (record_preview_ready)
02:55:02.905 (+2.0s) - NotificationService.create_user_recipe (facility_new_project, record_processing_completed)
02:55:04.906 (+2.0s) - NotificationService.subscribe
02:55:05.474 - Response sent [200]
Total: 10546.5ms (DB time: 127.2ms)

상위 5개 느린 요청:

text

| Timestamp          | Duration  | DB time | User                         | Region          |
|--------------------|-----------|---------|------------------------------|-----------------|
| 02:55:05.474       | 10546.5ms | 127.2ms | mark.hickey@auav.com.au      | ap-southeast-2  |
| 04:08:41.796       | 5063.8ms  | 114.7ms | mark.hickey@auav.com.au      | ap-southeast-2  |
| 06:13:34.401       | 6952.6ms  | 81.2ms  | marioobeid@built.com.au      | ap-southeast-2  |
| 04:17:32.111       | 3679.3ms  | 35.6ms  | mario.basile1@hawkins.co.nz  | ap-southeast-2  |
| 03:44:53.107       | 3523.5ms  | 140.2ms | glenn.kemara@unispace.com    | ap-southeast-2  |

리전별 지연 분포:

text

ap-southeast-2: 32 requests, avg 1924ms
us-west-2: 18 requests, avg 1034ms

호스트별 분석 — ip-10-1-145-251 (ap-southeast-2)가 평균 2268ms로 가장 느림:

text

ip-10-1-145-251 (ap-southeast-2): 18 requests, avg 2268ms
ip-10-1-17-211 (ap-southeast-2): 6 requests, avg 1912ms
ip-10-1-83-125 (ap-southeast-2): 8 requests, avg 1158ms
ip-10-1-80-134 (us-west-2): 6 requests, avg 1138ms

Hypotheses Considered#

#	Hypothesis	Evidence for	Evidence against	Verdict
H1	NotificationService 동기 호출이 요청 스레드를 블로킹하여 지연 발생	Trace 타임라인에서 NotificationService 호출 구간이 ~8s 차지; `user_recipe_generator.rb:40`에서 3회 순차 HTTP POST; `http_client.rb`가 RestClient(동기) 사용	—	Confirmed
H2	데이터베이스 slow query로 인한 지연	—	DB time 35~~171ms (전체 대비 3~~8%); slow query 로그 없음	Rejected
H3	Elasticsearch 인덱싱 지연	`searchable.rb:12-13`에서 after_commit 동기 인덱싱; `as_indexed_json`에서 81개 속성 직렬화	10.5s 중 ES 구간은 trace에서 1s 미만으로 추정; 주 지연은 NotificationService 구간에 집중	Rejected (주 원인 아님, 보조 요인)
H4	ap-southeast-2에서 notification-service까지 네트워크 지연이 추가로 증폭	ap-southeast-2 평균 1924ms vs us-west-2 1034ms (거의 2배 차이)	동일 notification-service URL 사용 — 서비스 위치가 us-west-2라면 cross-region 레이턴시 추가	Confirmed (보조 요인)

Fix Recommendation#

즉시 조치 (Critical)#

lib/cupix/pub_sub/subscribers/user_recipe_generator.rb:40 — create_user_recipe 호출을 Sidekiq worker로 비동기 전환. 현재 .each 루프 안에서 3회 동기 HTTP 호출이 요청 스레드를 블로킹하고 있음.
lib/cupix/pub_sub/subscribers/subscription_generator.rb:21 — subscribe 호출도 동일하게 worker 비동기 전환.
방향: NotificationRecipeWorker.perform_async(user_id, recipe_name, team_id, facility_key) 패턴으로 HTTP I/O를 요청 밖으로 분리.

단기 개선 (1주 이내)#

PubSub::Publisher (app/models/concerns/pub_sub/publisher.rb:41-44)에서 after_commit 콜백 내 subscriber 실행을 기본적으로 비동기화하는 인프라 레벨 개선 검토. 현재는 모든 subscriber가 동기 실행됨.
notification-service 호출에 timeout 설정 추가 (현재 RestClient 기본 timeout 무제한). open_timeout: 2, timeout: 5 권장.

장기 개선 (재발 방지)#

notification-service가 us-west-2에만 배포된 경우, ap-southeast-2 리전에 replica 배포하여 cross-region 레이턴시 제거.
PubSub 아키텍처를 event queue 기반 (SQS/SNS 또는 Redis Streams)으로 전환하여 subscriber 실행이 요청 수명주기와 완전 분리되도록 개선.

Monitoring#

Capture create 엔드포인트 p95 latency 알림 (threshold: 3000ms):

text

avg(last_5m):trace.rack.request.duration{service:cupixworks-api, resource_name:api::v1::capturescontroller_create} > 3000000000

NotificationService HTTP 호출 duration 메트릭 추가 (caller-side):

text

service:cupixworks-api @class:Cupix::NotificationService @function:create_user_recipe

PubSub subscriber 실행 시간 모니터링 추가

Risk Assessment#

Risk level: medium
예상 복잡도: standard — subscriber 호출을 worker로 래핑하는 비교적 단순한 변경이나, 비동기 전환 시 recipe 생성 실패에 대한 재시도 로직과 에러 핸들링 검증 필요.