RCA: Api::V1::ReviewsController#create Latency (4349ms)

Overview#

What Happened#

2026-05-31 ap-southeast-2 리전에서 Api::V1::ReviewsController#create 요청이 4,349ms로 완료되었다. HTTP 200으로 성공했으나, DB 쿼리 시간은 59ms에 불과하고 나머지 ~4,290ms가 애플리케이션 레벨 동기 처리(Elasticsearch 인덱싱, AWS Kinesis 이벤트 발행, Draftable 재저장, Segment 분석 등)에 소비되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-06-01 08:46:38 KST — ReviewsController#create 요청 수신
2. 2026-06-01 08:46:40 KST — UserFactory group provisioning + permission cache flush 시작
3. 2026-06-01 08:46:40 KST — EventService.publish_event 완료 (Kinesis put_records!)
4. 2026-06-01 08:46:42~43 KST — NotificationService recipe 생성 (3건 순차 처리)
5. 2026-06-01 08:46:43 KST — 요청 완료 (HTTP 200, 4347ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::ReviewsController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 4349,
  "max_ms": 4349,
  "sample_trace_id": "3197111432434643601"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-01 08:46 KST
• 최근 발생: 2026-06-01 08:46 KST

Root Cause Summary#

Review 생성 시 model.save! 이후 동기적으로 실행되는 다수의 외부 서비스 호출과 콜백 체인이 누적되어 4.3초의 응답 지연이 발생했다. 핵심 원인은 (1) after_commit에서 Elasticsearch에 동기 인덱싱, (2) after_create에서 AWS Kinesis에 동기 이벤트 발행, (3) Draftable 콜백의 불필요한 재저장(2차 콜백 트리거), (4) Segment Analytics 동기 호출이 순차적으로 실행된 것이다. DB 시간은 59ms에 불과하므로 순수 네트워크 I/O 대기가 대부분의 지연을 차지한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/reviews_controller.rb:25
• Factory: app/factories/review_factory.rb:32 → app/factories/base_factory.rb:124 (model.save!)
• Failure point (latency): 다수의 after_create / after_commit 콜백

1. Controller → Factory 호출

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

def create!(params)
  @facility = FacilityRepository.new(current_user: current_user).show(params[:facility_key])
  # ... 중복 facility 조회 (set_facility before_action에서 이미 수행)
  raise ... if team.reviews.count >= team.max_reviews_count  # 전체 COUNT 쿼리
  super
end

team.reviews.count는 해당 팀의 전체 리뷰 수를 카운트하는 unbounded 쿼리로, 팀 규모에 따라 50~500ms 소요 가능.

2. model.save! 이후 동기 콜백 체인

after_create :create_event_and_publish
# → Eventable::Events::Create.create_event(model)
# → Cupix::EventService.publish_event([event])  ← 동기 Kinesis 호출

def self.publish_event(events)
  kinesis_client.put_records(...)  # 동기 AWS API call (100-1000ms)
end

after_create :save_as_draft
# PaperTrail::Version 생성 후 self를 다시 find + save → 2차 콜백 트리거
def save_as_draft
  PaperTrail::Version.create(...)
  record = self.class.find_by_id(self.id)
  record.save(touch: false)  # ← after_save/after_commit 콜백 재실행
end

save_as_draft가 레코드를 다시 로드하고 save를 호출하면 Firebase, Elasticsearch, cache 관련 after_save/after_commit 콜백이 2번째로 실행된다.

after_commit :_index_document, on: [:create, :update]
# → 동기 HTTP call to Elasticsearch (500-2000ms under load)
def _index_document
  __elasticsearch__.index_document  # 동기 ES 인덱싱
end

3. Segment Analytics 동기 호출

Analytics.track(...)  # 동기 Segment API call (50-300ms)

실행 순서 요약:

1. model.save! (DB: ~59ms)
2. after_create: Eventable → Kinesis put_records! (동기, ~100-1000ms)
3. after_create: Analytics.track (동기, ~50-300ms)
4. after_create: Draftable#save_as_draft → PaperTrail + 재저장 → 2차 콜백 트리거 (~200-500ms)
5. after_commit: Searchable#_index_document → ES 동기 인덱싱 (×2회, ~500-2000ms)
6. after_commit: counter_culture facility update (~20-100ms)

이 모든 동기 작업이 순차 실행되어 합산 4,349ms가 소요되었다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api @http.url_details.path:"/api/v1/reviews" @trace_id:3197111432434643601

service:cupixworks-api @request_id:55c97951-376c-48c1-96bd-1d0170ac3798

요청 완료 로그:

{
  "controller": "Api::V1::ReviewsController",
  "action": "create",
  "method": "POST",
  "path": "/api/v1/reviews",
  "status": 200,
  "duration": 4347.05,
  "db": 59.43,
  "view": 0.06,
  "params": {"name": "BWC - Client View", "facility_key": "mnmt4e"},
  "user": "alunwelsh@built.com.au",
  "team": "built",
  "host": "ip-10-1-83-67.ap-southeast-2.compute.internal"
}

동일 request_id로 추적된 인라인 활동:

23:46:40.194Z [info] UserFactory#update_user_groups! - User 231 added to group 579ae16e...#951
23:46:40.194Z [warn] Group#_update_document - NotFound - attributes_in_database
23:46:40.194Z [info] Module#flush_cached_permissions - Flush cached permissions for User 231
23:46:40.194Z [info] Cupix::EventService#publish_event - Published event (Review#12215)
23:46:43.562Z [info] Request completed - [200] POST /api/v1/reviews (4347.05ms)

DB 시간 59ms vs 전체 4347ms — 차이(~4288ms)는 동기 외부 호출(ES, Kinesis, Segment)과 콜백 재실행에서 발생.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

1. Elasticsearch 인덱싱을 비동기로 전환 — app/models/concerns/searchable.rb:12-14

   • _index_document를 Sidekiq worker로 위임하여 after_commit에서 perform_async만 호출
   • 이것만으로 1-2초 절감 예상

2. Kinesis 이벤트 발행을 비동기로 전환 — lib/cupix/event_service.rb:43

   • put_records! 호출을 Sidekiq worker로 이동하거나 SQS 큐에 위임

단기 개선 (1주 이내)#

1. Draftable#save_as_draft 리팩토링 — app/models/concerns/draftable.rb:35-45

   • find_by_id + save 대신 update_column(:drafted_at, ...) 사용하여 콜백 재실행 방지
   • 이렇게 하면 ES, Firebase 등 2차 콜백이 불필요하게 트리거되지 않음

2. ReviewFactory에서 중복 facility 조회 제거 — app/factories/review_factory.rb:9

   • set_facility before_action에서 이미 로드된 facility를 재사용

3. team.reviews.count 최적화 — app/factories/review_factory.rb:21

   • counter_culture로 관리되는 reviews_count 캐시 컬럼을 활용하거나, limit 쿼리로 교체

장기 개선 (재발 방지)#

1. 콜백 기반 아키텍처를 이벤트 기반으로 전환 — 현재 20+ concern의 콜백이 save! 한 번에 순차 실행되는 구조는 예측 불가능한 지연을 유발. Domain event + async subscriber 패턴으로 마이그레이션 검토.

2. 외부 서비스 호출 표준화 — 모든 동기 외부 호출(ES, Kinesis, Segment)을 async-by-default로 전환하는 가이드라인 수립.

Monitoring#

• ReviewsController#create p95/p99 응답 시간 추적:

service:cupixworks-api resource_name:"Api::V1::ReviewsController#create" @duration:>2000ms

• Elasticsearch 인덱싱 지연 모니터링:

service:cupixworks-api "index_document" @duration:>500ms

• Kinesis publish 지연 추적:

service:cupixworks-api "publish_event" @duration:>300ms

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — 비동기 전환은 기존 Sidekiq 인프라 활용 가능하나, 콜백 의존성 검증 필요