RCA: Api::V1::FloorplansController#create Latency (avg 1166ms)

Overview#

What Happened#

2026-05-27 01:26~01:55 UTC 사이에 ap-southeast-2 리전의 cupixworks-api 서비스에서 FloorplansController#create 엔드포인트가 평균 1166ms, 최대 1197ms의 응답 시간을 기록했다. 동일 사용자(user_id: 1454, team: mtpo-vida)가 연속으로 floorplan을 업로드하는 과정에서 2건이 1000ms 임계값을 초과했다.

Quick Facts#

Timeline#

1. 2026-05-27 01:26:41Z — 첫 번째 느린 요청 발생 (1195ms, "Aerial Image 2 - Origin.png")
2. 2026-05-27 01:55:40Z — 두 번째 느린 요청 발생 (1131ms, "Aerial Image 6.png")
3. 2026-05-27 01:56:02Z — 세 번째 느린 요청 (1171ms, "Aerial Image 7.png") — 클러스터 기간 외이지만 동일 패턴

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FloorplansController#create",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 1166,
  "max_ms": 1197,
  "sample_trace_id": "2361297146223062686"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-05-27T01:26:39.055Z
• 최근 발생: 2026-05-27T01:55:39.334Z

Root Cause Summary#

FloorplansController#create 요청 시 모델 저장 후 동기적으로 실행되는 다수의 after_create/after_commit 콜백이 누적되어 총 응답 시간이 1000ms를 초과한다. Datadog 로그에서 DB time은 193ms, view time은 0.06ms에 불과하나 전체 duration은 11661197ms로, 약 970ms가 콜백에서 소비된다. 주요 병목: Elasticsearch 동기 인덱싱(Searchable#_index_document), Redis 캐시 쓰기(Cachable#write_cache), Event 레코드 생성(Eventable::Events::Create), Resource 레코드 생성(Resourcable::Floorplan#around_create_floorplan). ap-southeast-2 리전의 Elasticsearch/Redis 레이턴시가 상대적으로 높아 콜백 체인의 누적 효과가 더 크게 나타난다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/floorplans_controller.rb:28-31

def create
  @model = factory_instance.create!(params)
  super  # renders response via render_api
end

• Factory creation: app/factories/floorplan_factory.rb:5-66

if params[:level_id].present?
  level = LevelRepository.new(current_user: self.current_user).show(params[:level_id])

LevelRepository#show는 permission joins를 포함한 복잡한 쿼리를 실행한다(DB ~193ms의 일부).

• Model save triggers callback chain: app/factories/base_factory.rb:124 → model.save!

콜백 실행 순서:

1. before_create — Storagable#set_storage, Properties::Floorplan#copy_name_to_meta
2. around_create — Resourcable::Floorplan#around_create_floorplan (Resource 레코드 DB INSERT)

def around_create_floorplan
  yield
  self.resources.create user: self.user, name: self.name, team: self.team
  nil
end

3. after_create — Eventable::Callbacks (Event 레코드 생성)

after_create do |model|
  Eventable::Events::Create.create_event(model) if model.event_creation_on_create?
end

def _create_event(model)
  event = EventFactory.new(current_user: model.current_user).create!(model)

4. after_create — LevelEntity::Floorplan#set_level_default_floorplan (조건부 DB UPDATE)
5. after_commit — Searchable#_index_document (동기 Elasticsearch HTTP 호출)

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))

6. after_commit — Cachable#write_cache (Redis serialization + write)

def write_cache(force: false)
  prior_to_write_cache
  _cache_keys = []
  _cache_value = nil

  if cachable? && respond_to?(:serialized_json)
    _cache_value = self.send(:serialized_json)
    # ... serializes full model then writes to Redis
    _cache_keys.each do |_cache_key|
      Rails.cache.write(_cache_key, _cache_value, expires_in: self.class.cache_expires_in)
    end
  end
end

• Failure point (bottleneck): app/models/concerns/searchable.rb:43 — Elasticsearch index 호출이 ap-southeast-2 리전에서 네트워크 왕복 시간을 포함하여 단일 호출에 200-500ms가 소요될 수 있다.

Log Evidence#

Datadog 검색에서 확인된 요청별 성능 분석:

service:cupixworks-api resource_name:"Api::V1::FloorplansController#create" env:production @http.status_code:200 @duration:>500000000

동일 사용자 7건의 요청 중 duration/DB time 비교:

| Timestamp (UTC) | File Name                    | Duration (ms) | DB Time (ms) | Gap (ms) |
|-----------------|------------------------------|---------------|--------------|----------|
| 01:26:41        | Aerial Image 2 - Origin.png  | 1195.63       | 193.19       | 1002.44  |
| 01:28:17        | Aerial Image 1.png           | 592.11        | 224.95       | 367.16   |
| 01:54:00        | Aerial Image 3.png           | 641.72        | 195.31       | 446.41   |
| 01:55:40        | Aerial Image 6.png           | 1131.16       | 186.91       | 944.25   |
| 01:56:02        | Aerial Image 7.png           | 1171.81       | 191.27       | 980.54   |

• DB time은 일관적으로 190ms 이나, 총 duration은 5921197ms로 변동이 크다.
• Gap(비-DB 시간)이 367~1002ms 범위로, 이는 외부 서비스(Elasticsearch, Redis) 호출의 네트워크 레이턴시 변동과 일치한다.
• 다른 팀(downergroup)의 동일 엔드포인트 요청은 399ms(DB 56ms)로 빠르게 처리됨 — 팀별 데이터 크기와 permission join 복잡도가 DB time에 영향을 미침.
• 에러 레벨 로그는 없으며, 모든 요청이 HTTP 200으로 완료됨.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/searchable.rb:12-14 — after_commit on: [:create]에서 동기 Elasticsearch 인덱싱을 비동기 워커(BulkIndexWorker)로 전환. 현재 에러 발생 시에만 fallback으로 BulkIndexWorker를 사용하고 있으나, 정상 경로에서도 비동기로 처리해야 한다.
• 변경 방향: _index_document 대신 BulkIndexWorker.perform_async(self.class.name, [id], 'index')를 기본으로 호출.

단기 개선 (1주 이내)#

• Cachable#write_cache의 serialized_json 호출이 전체 serializer를 실행하므로, 캐시 쓰기도 비동기 처리하거나 경량화된 캐시 값을 사용하도록 변경.
• Eventable::Events::Create의 event 생성을 비동기 워커로 위임하여 HTTP 요청 스레드에서 분리.

장기 개선 (재발 방지)#

• after_commit 콜백 체인을 감사하여, HTTP 요청 내에서 반드시 동기적으로 실행해야 하는 콜백과 비동기로 전환 가능한 콜백을 분류.
• ap-southeast-2 리전의 Elasticsearch 클러스터 위치 또는 Redis 엔드포인트의 네트워크 근접성 검토.
• 복잡한 permission JOIN을 가진 repository 쿼리에 대해 인덱스 최적화 또는 캐시 레이어 도입 검토.

Monitoring#

• FloorplansController#create p95 latency 알림 설정 (임계값 800ms)
• Elasticsearch 인덱싱 레이턴시 모니터링:

service:cupixworks-api @message:"_index_document" @duration:>200ms env:production

• after_commit 콜백 체인 총 실행 시간 추적을 위한 custom metric 도입 고려

Risk Assessment#

• Risk level: low
• 예상 복잡도: standard — Elasticsearch 인덱싱의 비동기 전환은 이미 에러 경로에서 BulkIndexWorker를 사용하고 있어 패턴이 검증됨. 단, 검색 결과의 eventual consistency를 수용해야 함.