RCA: Api::V1::LevelsController#create Latency (avg 6948ms, max 8472ms)

Overview#

What Happened#

2026-05-26 04:07~04:28 UTC 사이에 ap-southeast-2 리전의 cupixworks-api 서비스에서 Api::V1::LevelsController#create 요청 2건이 평균 6948ms, 최대 8472ms의 비정상적 응답 시간을 기록했다. 데이터베이스 쿼리 시간은 62ms에 불과하며, 나머지 ~8400ms는 after_create 콜백에서 동기적으로 수행되는 Workarea/Spacetime 생성, Elasticsearch 인덱싱, 알림 서비스 구독 생성에 소비되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-05-26T04:07:12Z — cupix 테넌트에서 "LEVEL 8" 생성 요청 (5421ms)
2. 2026-05-26T04:28:25Z — nswgov 테넌트에서 facility a04jas의 첫 level "GF" 생성 요청 (8472ms)
3. 2026-05-26T04:28:41Z — 동일 facility에서 두 번째 level "L1" 생성 (316ms — 구독 이미 생성됨)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::LevelsController#create",
  "service": "cupixworks-api",
  "occurrences": 2,
  "avg_ms": 6948,
  "max_ms": 8472,
  "sample_trace_id": "1236946669674929894"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 2
• 최초 발생: 2026-05-26T04:07:12.948Z
• 최근 발생: 2026-05-26T04:28:25.607Z

Root Cause Summary#

Level 생성 시 after_create 콜백 체인에서 동기적으로 수행되는 무거운 작업들이 응답 시간을 극도로 지연시킨다. 핵심 원인은 세 가지이다: (1) create_not_set_workarea가 facility의 모든 non-default workarea_group에 대해 Workarea를 순차 생성하며 각각 Elasticsearch 인덱싱을 동기 호출, (2) create_spacetimes가 facility의 모든 record에 대해 Spacetime.find_or_create_by!를 순차 실행, (3) 알림 서비스(Cupix::NotificationService)에 대한 동기 HTTP 호출로 subscription과 recipe를 생성. DB 시간이 62ms에 불과한 반면 총 응답 시간이 8472ms인 것은 이 동기 외부 호출들이 대부분의 시간을 점유했음을 명확히 보여준다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/levels_controller.rb:24
• Factory 생성: app/factories/level_factory.rb:5
• Model save (콜백 트리거): app/factories/base_factory.rb:124
• after_create — default models 생성: app/models/concerns/has_default/level.rb:16
• after_create — spacetime 생성: app/models/concerns/spacetime_element/level.rb:10
• after_commit — ES 인덱싱: app/models/concerns/searchable.rb:12-13

1. Controller → Factory 호출

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

factory_instance는 LevelFactory를 인스턴스화하고, create!에서 model.save!를 호출하여 모든 콜백이 트리거된다.

2. after_create: create_not_set_workarea — O(N) Workarea 생성

facility의 모든 non-default workarea_group에 대해 순차적으로 Workarea를 생성한다. 각 Workarea.create!는 Searchable concern을 통해 after_commit에서 동기 Elasticsearch HTTP 인덱싱을 수행한다.

def create_not_set_workarea
  workarea_groups = self.facility.workarea_groups.untrashed

  workarea_groups.find_each do |workarea_group|
    next if workarea_group.is_default

    ::Workarea.create!(
      level_id: self.id,
      name: 'not_set',
      workarea_group_id: workarea_group.id,
      is_default: false,
      team_id: self.team_id,
      user_id: self.user_id,
      workarea_type: 'not_set'
    )
  end
end

3. after_create: create_spacetimes — O(M) Spacetime upsert

facility의 모든 record에 대해 find_or_create_by!를 호출한다. record 수가 많을수록 선형적으로 시간이 증가한다.

def create_spacetimes
  created = 0

  facility.records.each do |record|
    Spacetime.find_or_create_by!({
      team: team,
      workspace: workspace,
      facility: facility,
      record: record,
      level: self
    })

    created += 1
  end

  created
end

4. after_commit: 동기 Elasticsearch 인덱싱

Level, Sketch, 각 Workarea 모두 생성 후 동기적으로 ES에 인덱싱한다. 네트워크 latency × 생성된 모델 수만큼 시간이 누적된다.

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))
  Cupix::Logger.debug(results.to_json, class: self.class.name, function: __method__)

  # NOTE: dual write to tmp_index while reindexing
  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

Log Evidence#

Datadog 쿼리 (cupixworks-api request logs):

service:cupixworks-api @http.url_details.path:/api/v1/levels @http.method:POST env:production

핵심 로그 — 8472ms 요청 (request_id: 57d08b5e-b619-4c07-beca-36ef56d2d29b):

[2026-05-26T04:28:41.626Z] Api::V1::LevelsController#create
  duration: 8471.17ms | db: 62.17ms | view: 0.06ms
  tenant: nswgov | team: sinsw | user: eva.revina@cupix.com
  host: ip-10-1-80-92.ap-southeast-2
  params: {facility_key: "a04jas", name: "GF"}

동일 요청 중 발생한 동기 작업 로그:

[04:28:xx] Flush cached permissions for User 26
[04:28:xx] Flush cached permissions By User for User 26 on Level 43229
[04:28:xx] Cachable::ReviewLoad | Invalidated facility review cache on create | model=Level | model_id=43229 | facility_id=2450
[04:28:xx] subscription of eva.revina@cupix.com on Facility a04jas created
[04:28:xx] Cupix::NotificationService - created recipe: facility_new_project
[04:28:xx] Cupix::NotificationService - created recipe: record_preview_ready
[04:28:xx] Cupix::NotificationService - created recipe: record_processing_completed
[04:28:xx] Cupix::SiteinsightsService::EventProducer.produce - Workarea create (0/1 published)

비교 — 동일 facility 두 번째 level "L1" (316ms):

[2026-05-26T04:28:41.626Z] Api::V1::LevelsController#create
  duration: 316.49ms | db: 57.45ms
  tenant: nswgov | params: {name: "L1"}

두 번째 요청은 subscription/recipe가 이미 생성되어 있어 알림 서비스 호출이 스킵되었고, 정상 응답 시간을 보여준다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/has_default/level.rb:50-65 — create_not_set_workarea에서 Workarea 생성을 비동기 worker로 이동. Level 생성 응답에는 Workarea가 즉시 필요하지 않으므로, Sidekiq worker에서 bulk 생성하도록 변경.
• 알림 서비스 subscription/recipe 생성 — 현재 Level의 after_create 콜백 체인 내에서 동기 HTTP 호출로 수행됨. 이를 비동기 worker (CreateNotificationSubscriptionWorker 등)로 분리.

단기 개선 (1주 이내)#

• app/models/concerns/spacetime_element/level.rb:10-26 — create_spacetimes를 비동기 worker로 이동하거나, insert_all을 사용하여 bulk insert로 변경. find_or_create_by! 루프는 record 수에 비례하여 느려진다.
• Elasticsearch 인덱싱 — Level 생성 시 연쇄적으로 생성되는 Sketch, Workarea들의 _index_document를 즉시 실행하지 않고, bulk index worker를 통해 일괄 처리하도록 변경 (skip_index_document! 활용 후 BulkIndexWorker 호출).

장기 개선 (재발 방지)#

• Level 생성의 after_create 콜백 체인을 경량화하여 동기 작업은 DB 저장만 수행하고, 모든 부수 작업(Workarea 생성, Spacetime 생성, ES 인덱싱, 이벤트 발행, 알림 구독)은 비동기 처리 파이프라인으로 이관.
• CreateLevelPostProcessWorker 같은 단일 worker를 도입하여 모든 후처리를 순서대로 비동기 실행.

Monitoring#

• LevelsController#create p95/p99 latency 모니터링 추가
• Datadog APM 쿼리:

service:cupixworks-api resource_name:"Api::V1::LevelsController#create" env:production @duration:>3s

• 알림 서비스 호출 latency 별도 추적 (Cupix::NotificationService 호출 시간)
• Workarea 생성 수 대비 응답 시간 상관관계 대시보드

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard — 콜백을 비동기 worker로 분리하는 작업은 기존 패턴(BulkIndexWorker, Sidekiq)을 따르면 됨. 다만 기능 정합성(Level 생성 직후 Workarea 조회 시 아직 생성되지 않은 상태) 처리 필요.