RCA: Api::V1::WorkareaGroupsController#create (avg 13004ms, max 13004ms)

Overview#

What Happened#

2026-07-23 06:42 KST 에 cupixworks-api (us-west-2) 에서 POST /api/v1/workarea_groups 한 건이 12,996ms 걸려 정상 응답(200)했다. 동일 엔드포인트의 최근 7일 평균은 150ms 수준이므로 약 85배 느린 이상치이며, 대상 facility(y6he2m — "343 Madison Project", team Turner Construction) 는 55개의 level 을 보유해 WorkareaGroup after_create 콜백이 55회의 Workarea.create! 를 동기 실행하면서 각각 Elasticsearch 인덱싱까지 수행한 것이 지연의 주된 원인이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-23 06:41:06 KST — 동일 사용자가 facility y6he2m 를 조회 (GET /api/v1/facilities/y6he2m, 정상)
2. 2026-07-23 06:42:13 KST — POST /api/v1/workarea_groups (name="Work Area Group 0", facility_key="y6he2m") 요청 시작 (first_seen)
3. 2026-07-23 06:42:27 KST — 요청 완료 (200, duration=12996.72ms, db=4569.36ms)
4. 2026-07-23 06:42:38 KST — 후속 GET /api/v1/facilities/y6he2m 정상 응답 (관련 조회는 회복)

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::WorkareaGroupsController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 13004,
  "max_ms": 13004,
  "sample_trace_id": "1942084312286998617"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-23 06:42:13 KST
• 최근 발생: 2026-07-23 06:42:13 KST

단일 요청 (Turner Construction 팀, 사용자 Matt Muir) 이 12,996ms 동안 UI 를 블로킹했다. 응답 자체는 200이므로 데이터 정합성 문제는 없다. 다만 동일 facility (y6he2m = 55 levels, "343 Madison Project", 900,000 sqft) 에서 추가로 WorkareaGroup 을 만들 때마다 유사한 지연이 재현될 것이며, level 이 더 많은 facility 에서는 timeout (nginx/ELB 60s) 위험이 있다.

Root Cause Summary#

WorkareaGroup 이 생성되면 after_create :create_not_set_workarea 콜백이 실행되어 facility 의 모든 untrashed level 을 조회한 뒤 각 level 마다 ::Workarea.create! 를 순차 호출한다 (app/models/workarea_group.rb:17-36). 이번 요청 대상 facility 는 level 이 55개였고, 각 Workarea.create! 마다 Searchable 의 after_commit :_index_document 와 EntityIndexable 의 _entity_index_document 가 Elasticsearch 로 동기 인덱스 요청을 보낸다 (app/models/concerns/searchable.rb:12-14,34-53, app/models/concerns/entity_indexable.rb:42-45,160-170). 결과적으로 요청 하나가 55회의 DB INSERT + 최소 110회 (55 × 2 인덱스) 의 동기 ES 인덱싱을 트리거해 13초에 이르는 지연이 발생한다. 로그에서 db=4569.36ms, duration=12996.72ms, view=0.09ms 는 지연의 대부분이 DB 쿼리 시간 (4.6s) 과 Elasticsearch 왕복 (~8.4s) 이라는 점을 뒷받침한다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/workarea_groups_controller.rb:21 (WorkareaGroupsController#create)
• Factory: app/factories/workarea_group_factory.rb:7-17 → BaseFactory#create! (app/factories/base_factory.rb:80-141) → self.model.save!
• Failure point (latency): app/models/workarea_group.rb:17-36 (after_create :create_not_set_workarea) 및 각 Workarea.create! 의 인덱싱 콜백

Controller 진입점:

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

  super
end

Factory 는 WorkareaGroup 인스턴스를 만들어 BaseFactory#create! 로 저장한다:

def create!(params = {})
  check_required_parameter(params)

  self.model = ::WorkareaGroup.new
  self.model.facility = FacilityRepository.new(current_user: self.current_user).show(params[:facility_key])
  self.parent = self.model.facility
  self.model.is_default = ActiveRecord::Type::Boolean.new.cast(params[:is_default]) unless params[:is_default].nil?
  self.model.is_room = ActiveRecord::Type::Boolean.new.cast(params[:is_room]) unless params[:is_room].nil?

  super
end

WorkareaGroup#save! 이 성공하면 아래 after_create 콜백이 실행되어 모든 level 에 대해 Workarea 를 순차 생성한다:

after_create :create_not_set_workarea, unless: :is_default

def create_not_set_workarea
  levels = self.facility.levels.untrashed

  return if ::Workarea.where(workarea_group_id: self.id, facility_id: self.facility_id).not_set.untrashed == levels.size

  existing_level_ids = ::Workarea.where(level_id: levels.select(:id), workarea_group_id: self.id).not_set.untrashed.pluck(:level_id)
  levels.where.not(id: existing_level_ids).find_each do |level|
    ::Workarea.create!(
      level_id: level.id,
      name: 'not_set',
      workarea_group_id: self.id,
      is_default: false,
      team_id: self.team_id,
      user_id: self.user_id,
      workarea_type: 'not_set'
    )
  end
end

각 Workarea 는 두 가지 Elasticsearch 인덱스 콜백을 상속받아, after_commit :create 시점에 동기 HTTP 요청을 보낸다:

after_commit on: [:create] do
  _index_document
end
# ...
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))
  # ...
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

included do
  after_commit :_entity_index_document, on: [:create]
  after_commit :_entity_update_document, on: [:update]
  after_commit :_entity_delete_document, on: [:destroy]
end
# ...
def _entity_index_document
  return if @skip_index_document == true

  Elasticsearch::Model.client.index(
    index: self.class.entity_index_name,
    id: entity_document_id,
    body: as_entity_indexed_json
  )
rescue StandardError => e
  Cupix::Logger.error("Entity index error - #{e.message}", class: self.class.name, function: __method__)
end

Workarea 도 두 관심사를 모두 include 하므로 (app/models/workarea.rb:3,5), 하나의 Workarea.create! 는 최소 두 번의 동기 ES 인덱스 왕복을 발생시킨다. 결과적으로 55 levels 인 facility 에서 WorkareaGroup#create! 한 번은 55 INSERT + 110 이상의 동기 ES 인덱스 호출로 확장된다.

기대 동작: 새 workarea_group 생성 API 는 그룹 자체만 저장하고, level 별 not_set workarea 생성은 워커나 지연 실행 (bulk indexing / async job) 으로 위임되어 서브초 수준으로 응답. 실제 동작: HTTP 요청 처리 스레드가 55개의 Workarea 를 하나씩 만들고 각각에 대해 동기 ES 요청을 기다려 총 12,996ms 소요.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "POST /api/v1/workarea_groups"

시간 범위 2026-07-22T21:40:00Z ~ 2026-07-22T21:50:00Z 에서 이번 이상 요청 1건이 반환됐다. 원문 (raw 발췌):

{
  "duration": 12996.72,
  "db": 4569.36,
  "view": 0.09,
  "controller": "Api::V1::WorkareaGroupsController",
  "action": "create",
  "http": { "method": "POST", "path": "/api/v1/workarea_groups", "status_code": 200 },
  "params": {
    "name": "Work Area Group 0",
    "facility_key": "y6he2m"
  },
  "user": { "id": 38530, "email": "matthew.muir@cupix.com" },
  "team": { "id": 748, "domain": "tcco" },
  "@timestamp": "2026-07-22T21:42:27.110Z",
  "message": "[200] POST /api/v1/workarea_groups (Api::V1::WorkareaGroupsController#create)"
}

동일 쿼리를 7일 범위로 확장한 결과 (50건 표본) 에서 다른 요청들은 108706ms, db 26180ms 로 나타나 이번 건이 유일한 이상치임을 확인:

ts=2026-07-22T21:42:27.110Z dur=12996.72 db=4569.36 facility=y6he2m status=200
ts=2026-07-22T09:51:30.801Z dur=155.27    db=58.24   facility=fjv0xd status=200
ts=2026-07-22T09:18:46.677Z dur=143.19    db=40.10   facility=4g2he  status=200
ts=2026-07-21T17:41:54.232Z dur=705.88    db=177.55  facility=z0g66x status=200
ts=2026-07-20T21:10:10.763Z dur=647.88    db=155.76  facility=w39snf status=200
...

Kibana (Elasticsearch) 로 대상 facility 규모 확인:

index=facilities term=key:y6he2m         → id=19142, name="343 Madison Project", team.id=748 (tcco), facility_size=900000 sqft
index=levels    term=facility.id:19142    → 55 hits
index=workarea_groups term=facility.id:19142 → 2 hits
index=workareas term=facility.id:19142 AND name.sort=not_set → 55 hits

levels 개수 (55) 와 이후 not_set workareas 개수 (55) 가 정확히 일치하므로, 이번 요청이 55회의 Workarea.create! 를 순차 실행한 것이 로그의 duration 과 정합적이다. 다른 요청들이 빠른 이유는 대부분의 facility 가 level 수가 훨씬 적기 때문 (예: 155ms 요청은 db=58ms 로 level 몇 개만 처리).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 파일: app/models/workarea_group.rb:17-36
• 접근: after_create :create_not_set_workarea 콜백에서 순차 Workarea.create! 대신, level 별 Workarea 를 백그라운드 워커(Sidekiq) 로 위임하거나 최소한 insert_all / Workarea.create! 도중 skip_index_document! 로 인덱싱을 스킵하고 종료 시점에 BulkIndexWorker.perform_async 로 일괄 인덱싱한다. 이는 HTTP 응답 경로에서 55 × 2 회의 동기 ES 요청을 제거해 응답 시간을 subsecond 로 낮추는 것이 목적. 데이터 정합성 관점에서는 API 반환 시점에 not_set workarea 가 즉시 조회되지 않아도 되는지 프런트엔드 계약을 확인 필요 (조회는 별도 endpoint 이므로 대체로 안전하지만 UI 팀 확인 요망 — 자동 코드 수정 범위 밖).

단기 개선 (1주 이내)#

• 파일: app/models/concerns/searchable.rb:12-14,34-53, app/models/concerns/entity_indexable.rb:42-45,160-170
• 접근: bulk 인서트 경로에서만이라도 skip_index_document 를 활성화한 뒤 종료 시점에 BulkIndexWorker.perform_async(self.class.name, ids, 'index') 로 일괄 인덱싱해 요청 스레드에서 ES 왕복을 제거. Workarea 는 이미 BulkIndexWorker 대체 경로가 있으므로 (searchable.rb:52) 확장 여지 큼.
• Datadog trace 에 각 Workarea.create! 스팬이 나타나도록 커스텀 span (Datadog::Tracing.trace('workarea.create_not_set')) 을 추가해 다음 유사 이슈의 병목을 즉시 특정.

장기 개선 (재발 방지)#

• ActiveRecord 콜백 안에서 행 수에 선형인 외부 I/O (ES / 외부 API) 를 실행하는 패턴을 리뷰 가드레일로 정의. 모델 콜백이 aggregate 자식 리소스를 생성해야 한다면 도메인 서비스나 워커로 위임하는 것을 기본 규칙으로.
• Rails 요청 처리 경로에서의 P99 latency 알람 임계값 (duration:>5s) 을 컨트롤러/액션 단위로 걸어 이런 outlier 를 자동 감지.
• level 수가 큰 facility (>50) 에서 workarea_group 생성이 자주 실패/지연하는지 추적하기 위해 facility_id → level_count 분포를 대시보드에 추가.

Monitoring#

writing-datadog-monitoring-queries 가이드에 따라 monitor-only 문법 없이 dashboard 에 직접 쓸 수 있는 형태로 작성.

WorkareaGroupsController#create P95 응답 시간 (초 단위):

p95:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::workareagroupscontroller#create}

WorkareaGroupsController#create 요청 수 (분당 rate):

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:api::v1::workareagroupscontroller#create}.as_rate()

5초 초과 create 요청 카운트 (14일 로그 기반):

logs("service:cupixworks-api \"POST /api/v1/workarea_groups\" @duration:>5000").index("*").rollup("count").by("@params.facility_key")

Risk Assessment#

• Risk level: medium — 데이터 정합성 문제는 없고 발생 빈도가 1건에 불과하지만, facility 규모가 큰 신규 project 에서 재발 가능하고 60s 요청 timeout 및 사용자 UX 저하 위험이 있다.
• 예상 복잡도: standard — 콜백 리팩터링과 백그라운드 위임은 기존의 BulkIndexWorker 및 skip 플래그 인프라를 재사용해 구현 가능. 프런트엔드/모바일 클라이언트의 "생성 즉시 목록에 노출" 기대를 확인해야 하므로 API 계약 조율이 필요.