RCA: FloorplansController#complete_creation Latency (avg 1083ms)

Overview#

What Happened#

2026-05-26 03:31:22 UTC에 ap-southeast-2 리전의 cupixworks-api 서비스에서 Api::V1::FloorplansController#complete_creation 엔드포인트가 1083ms 응답 시간을 기록했다. 동일 시간대에 같은 사용자가 연속으로 floorplan을 생성하면서 여러 건의 1000ms+ 요청이 발생했다. DB 쿼리 시간은 ~163ms로 일정하나, 나머지 ~920ms가 애플리케이션 콜백 체인(counter_culture_fix_counts, Elasticsearch 인덱싱)에서 소요된다.

Quick Facts#

Timeline#

1. 2026-05-26T03:00:25Z — 동일 사용자의 batch complete_creation 시작 (floorplan 15301, 1259ms)
2. 2026-05-26T03:31:22Z — 클러스터에 캡처된 요청 (floorplan 15321, 1082ms)
3. 2026-05-26T04:21:02Z — 마지막 관측된 요청 (floorplan 15328, 748ms)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FloorplansController#complete_creation",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1083,
  "max_ms": 1083,
  "sample_trace_id": "4531299037407677102"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (클러스터 기준, 실제 동일 패턴 10건 이상)
• 최초 발생: 2026-05-26T03:31:22.021Z
• 최근 발생: 2026-05-26T03:31:22.021Z

Root Cause Summary#

complete_creation 요청 시 state machine transition의 after_transition 콜백에서 counter_culture_fix_counts가 동기적으로 호출되어 전체 Floorplan 테이블을 스캔하며 counter cache를 재계산한다. 이 작업은 본래 마이그레이션/유지보수용 메서드로, 매 요청마다 실행되면 O(N) 비용이 발생한다. 여기에 after_commit의 동기 Elasticsearch 인덱싱이 추가되어 총 응답 시간이 1000ms를 초과한다. DB 쿼리 자체는 ~163ms로 정상이며, 나머지 ~920ms는 이 두 동기 작업에서 소요된다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/floorplans_controller.rb:59
• Before action set_floorplan: app/controllers/api/v1/floorplans_controller.rb:79 — 13개 LEFT JOIN permission 쿼리 실행
• Repository call: app/repositories/floorplan_repository.rb:239-241
• State transition: app/models/concerns/statable/floorplan.rb:70-76 — complete_creating event 발생
• Bottleneck 1: app/models/concerns/statable/floorplan.rb:86-88 — after_transition에서 counter_culture_fix_floorplans_count 호출
• Bottleneck 2: app/models/concerns/searchable.rb:16-18 — after_commit에서 _update_document (Elasticsearch HTTP 호출)
• Failure point: app/models/concerns/statable/floorplan.rb:187-188

def complete_creation
  @model = repository_instance.complete_creation
  render_api Renderable.new({
    contents: @model
  })
end

def complete_creation
  self.model.complete_creating_state!
  self.model
end

complete_creating_state!은 state_machines gem이 자동 생성하는 메서드로, complete_creating event를 발생시키고 save!를 호출한다. 이 transition이 발생하면 아래 after_transition 콜백이 실행된다:

after_transition from: %I[creating], to: any do |model, transition|
  model.counter_culture_fix_floorplans_count
end

after_transition from: any, to: %I[creating] do |model, transition|
  model.counter_culture_fix_floorplans_count
end

counter_culture_fix_floorplans_count는 전체 Floorplan 테이블을 스캔하여 counter cache를 재계산한다:

def counter_culture_fix_floorplans_count
  ::Floorplan.counter_culture_fix_counts column_name: :floorplans_count
end

counter_culture_fix_counts는 counter_culture gem의 maintenance 메서드로, 모든 레코드를 조회해 부모 모델의 counter를 교정한다. LevelEntity::Floorplan에서 counter_culture 설정:

counter_culture :level,
                column_name: proc { |model| model.untrashed? ? 'floorplans_count' : nil },
                column_names: { ::Floorplan.untrashed.not_draft => :floorplans_count }

save! 완료 후 after_commit에서 Elasticsearch 동기 인덱싱이 실행된다:

after_commit on: [:update] do
  _update_document
end

기대 동작: complete_creation은 state만 변경하고 빠르게 응답해야 한다 (DB ~165ms + rendering ~1ms = ~170ms). 실제 동작: counter_culture_fix_counts (~500-700ms 추정) + Elasticsearch _update_document (~200-300ms 추정) = 총 ~1000ms+ 추가 소요.

Log Evidence#

Datadog에서 complete_creation 요청 로그를 조회한 결과, DB 시간 대비 총 응답 시간의 큰 차이가 확인되었다:

service:cupixworks-api complete_creation
Time window: 2026-05-26T02:30:00Z to 2026-05-26T04:30:00Z

10건의 요청 로그가 확인되었으며, 모두 HTTP 200으로 성공:

Timestamp           | Floorplan | Duration(ms) | DB Time(ms) | Gap(ms)
2026-05-26T03:00:25 | 15301     | 1259.08      | 195.83      | 1063.25
2026-05-26T03:22:48 | 15318     | 1249.86      | 175.79      | 1074.07
2026-05-26T03:28:34 | 15320     | 1120.88      | 170.51      | 950.37
2026-05-26T03:31:24 | 15321     | 1082.06      | 163.26      | 918.80 ← cluster sample
2026-05-26T03:15:48 | 15316     | 668.96       | 165.01      | 503.95
2026-05-26T03:19:30 | 15317     | 551.97       | 163.97      | 388.00

모든 요청의 공통 특징:

• 동일 사용자: Roy Choi (roy.choi@citycareproperty.co.nz), team "citycare"
• 동일 세션: 6a57c506444f452cdffd5799e02b0e1161089ab5
• DB 시간은 161-209ms로 일정하나, 총 응답 시간은 551-1259ms로 큰 편차
• Gap(Duration - DB Time)이 388-1074ms로, 애플리케이션 레이어에서 대부분의 시간이 소요됨

FacilityMailer 로그에서 floorplan done 상태 전환 후 이메일 발송도 확인됨:

[FacilityMailer] - Floorplan:15322 - update_on_facility with event: floorplan_done sent (03:34:44Z)
[FacilityMailer] - Floorplan:15323 - update_on_facility with event: floorplan_done sent (03:44:01Z)

Cache invalidation 로그도 동일 시간대에 관측됨:

Cachable::ReviewLoad | Invalidated facility review cache on create | model=Floorplan | model_id=15327 | facility_id=3745 (03:54:14Z)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 파일: app/models/concerns/statable/floorplan.rb:86-91
• after_transition 콜백에서 counter_culture_fix_floorplans_count 호출을 제거하거나, 비동기 worker로 이동해야 한다.
• counter_culture_fix_counts는 전체 테이블 재계산이므로 request cycle에서 실행하면 안 됨. 대신 counter_culture gem의 자동 increment/decrement가 정상 동작하고 있다면 fix_counts 호출 자체가 불필요하다.

단기 개선 (1주 이내)#

• counter_culture_fix_floorplans_count가 실제로 필요한 경우(counter 불일치 문제가 있는 경우), Sidekiq worker로 비동기 실행하도록 변경한다. CounterCultureFixWorker.perform_async(:floorplans_count) 형태로 request cycle에서 분리.
• Elasticsearch _update_document (searchable.rb:16-18)도 비동기로 전환을 검토한다. after_commit에서 직접 HTTP 호출 대신 ReindexWorker.perform_async(id) 패턴 적용.

장기 개선 (재발 방지)#

• counter_culture gem의 자동 카운터 관리가 정상 동작하는지 검증 후, fix_counts 호출을 daily cron job으로만 실행하는 구조로 전환.
• State machine transition 콜백의 실행 시간을 모니터링하여, 특정 콜백이 임계치를 초과하면 알림을 발생시키는 instrumentation 추가.

Monitoring#

• counter_culture_fix_counts 실행 시간 메트릭 추가
• Datadog APM에서 complete_creation 엔드포인트 P95 latency 모니터 설정:

avg(last_5m):p95:trace.rack.request{service:cupixworks-api,resource_name:Api::V1::FloorplansController#complete_creation} > 800

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard — after_transition 콜백 제거 또는 비동기화는 기존 counter_culture 자동 관리가 정상이면 안전하게 수행 가능. 단, counter 불일치 여부를 먼저 확인해야 함.