ES /docs

Facility callbacks — synchronous deep-copy ops block request

RCA: Api::V1::FacilitiesController#create Latency (avg 5695ms, max 10799ms)

Overview#

What Happened#

2026-05-26 03:2104:42 UTC 사이에 cupixworks-api 서비스의 Api::V1::FacilitiesController#create 엔드포인트가 평균 5,695ms, 최대 10,799ms의 응답 시간을 기록했다. ap-southeast-2 리전에서 14건의 요청이 확인되었으며, DB 처리 시간은 240425ms에 불과하지만 전체 응답 시간의 92~95%가 애플리케이션 레이어의 동기 콜백 체인에서 소비되고 있다.

Quick Facts#

Field Value
resource_name Api::V1::FacilitiesController#create
top_frame app/controllers/api/v1/facilities_controller.rb:105
runtime Ruby on Rails
env production, ap-southeast-2

Affected Teams#

Team / Domain Error Count Impact
citycare (team 183) 12 Facility 생성 시 4~10초 대기, 배치 작업 시 UX 저하
scs-assetfuture (team 165) 1 단일 요청 10.8초 대기
arcadis01 (team 135) 1 단일 요청 10.8초 대기

Timeline#

  1. 2026-05-26 02:37 UTC — 최초 고지연 요청 발생 (arcadis01, 10,816ms)
  2. 2026-05-26 02:58~04:42 UTC — citycare 팀에서 12건 연속 배치 생성 (4,100~10,800ms)
  3. 2026-05-26 04:42 UTC — 마지막 고지연 요청 (scs-assetfuture, 10,798ms)
  4. 2026-05-26T05:00 UTC — Error sweeper 감지

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::FacilitiesController#create",
  "service": "cupixworks-api",
  "occurrences": 10,
  "avg_ms": 5695,
  "max_ms": 10799,
  "sample_trace_id": "37264198295551902"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 14건 (클러스터 기준 10건, 추가 검색으로 14건 확인)
  • 최초 발생: 2026-05-26T03:21:18.280Z
  • 최근 발생: 2026-05-26T04:42:19.564Z
  • 사용자 영향: Facility 생성 요청 시 4~10초 대기. 기능적 실패(에러)는 없으나 UX가 심각하게 저하됨.

Root Cause Summary#

Facility 생성 시 after_create 및 after_commit 콜백 체인이 모두 동기적으로 실행되면서 단일 HTTP 요청 내에서 다수의 DB 쓰기, Elasticsearch 인덱싱 HTTP 호출, Google Static Maps API 다운로드, 템플릿 복사 작업이 순차적으로 수행된다. DB 시간(240425ms)은 전체의 58%에 불과하며, 나머지 9295%(3,70010,400ms)는 Elasticsearch 네트워크 I/O, Google Maps API 호출, 다수 서브 모델 생성의 각각의 콜백 재귀 실행에 소비된다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/facilities_controller.rb:105-108
app/controllers/api/v1/facilities_controller.rb:105-108ruby
def create
  @model = factory_instance.create!(params)
  super  # renders response
end
  • FacilityFactory 초기화: app/factories/facility_factory.rb:5-37
app/factories/facility_factory.rb:5-37ruby
def create!(params = {})
  self.model = ::Facility.new

  if params[:workspace_id].present?
    self.parent = WorkspaceRepository.new(current_user: self.current_user).show(params[:workspace_id])
  end

  # ... asset_category_type, client lookups ...

  self.model.workspace = self.parent
  team = self.parent.team

  self.model.append_event_extra({
    facilities_count: team.facilities.count + 1  # COUNT query
  })
  self.model.track_team_event!
  super  # calls BaseFactory#create! → model.save!
end
  • after_create — Default 모델 생성 (동기): app/models/concerns/has_default/facility.rb:18-24
app/models/concerns/has_default/facility.rb:18-24ruby
def create_default_models
  create_default_workarea_group       # WorkareaGroup.create! + self.update
  create_ground_level unless skip_ground_level?   # LevelFactory.create! (+ Level 콜백)
  create_default_level unless skip_default_level? # LevelFactory.create! (+ Level 콜백)
end

각 Level 생성은 자체 after_create/after_commit 콜백(이벤트 생성, ES 인덱싱)을 재귀적으로 트리거한다.

  • after_create — 템플릿 복사 (동기): app/models/concerns/skeleton/facility.rb:8-9
app/models/concerns/skeleton/facility.rb:8-9ruby
after_create :create_default_annotation_layers
after_create :create_default_reviews
app/models/concerns/skeleton/facility.rb:11-40ruby
def create_default_annotation_layers
  return if self.team.domain == TEMPLATE_TEAM_DOMAIN

  template_annotation_layers = ::AnnotationLayer.eager_load(:team).untrashed.where(teams: { domain: TEMPLATE_TEAM_DOMAIN })
  copied_forms = self.team.form_designs.untrashed.select(&:cupix_template?)

  if copied_forms.present? && template_annotation_layers.present?
    template_annotation_layers.map do |annotation_layer|
      # ... hardcopy 생성 (DB write + ES index per layer) ...
    end
  end
end
  • after_commit — Elasticsearch 인덱싱 (동기 HTTP): app/models/concerns/searchable.rb:12-14, 34-53
app/models/concerns/searchable.rb:12-14ruby
after_commit on: [:create] do
  _index_document
end
app/models/concerns/searchable.rb:34-49ruby
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))

  # 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
end

이 콜백은 Facility뿐 아니라 Level, WorkareaGroup, AnnotationLayer, Review 등 모든 생성되는 모델마다 실행된다.

  • after_commit — Google Maps 썸네일 다운로드 (동기 HTTP): app/models/concerns/thumbnailable/facility.rb:14, 62-75
app/models/concerns/thumbnailable/facility.rb:62-74ruby
def change_thumbnail_job!
  return if self.google_static_map_url.nil?

  begin
    self.thumbnail = download_to_file(self.google_static_map_url)  # HTTP call to Google
    self.save  # triggers another after_commit cycle
  rescue StandardError => e
    Cupix::Logger.error("[Thumbnail][Facility] (#{id}) {change_thumbnail_job! - failed} : #{e.message}")
    raise e
  end
end
  • Failure point: 단일 실패 지점이 아닌 누적 지연 — 모든 콜백이 동기적으로 체이닝되어 총 지연이 합산됨.

Log Evidence#

Datadog에서 확인된 14건의 FacilitiesController#create 요청 로그:

text
service:cupixworks-api "FacilitiesController#create"

핵심 패턴 — DB 시간 vs 전체 시간 불일치:

json
{
  "timestamp": "2026-05-26T04:42:31.394Z",
  "duration_ms": 10797.98,
  "db_ms": 337.89,
  "view_ms": 0.06,
  "user": "Wing-Tim Choi",
  "team": "scs-assetfuture (165)",
  "facility_name": "St Joachim's Catholic Primary School Lidcombe"
}
json
{
  "timestamp": "2026-05-26T02:37:46.950Z",
  "duration_ms": 10815.78,
  "db_ms": 352.40,
  "user": "Eliza Shaw",
  "team": "arcadis01 (135)",
  "facility_name": "Sydney Tower Eye"
}
json
{
  "timestamp": "2026-05-26T03:27:10.567Z",
  "duration_ms": 6063.21,
  "db_ms": 241.06,
  "user": "Roy Choi",
  "team": "citycare (183)",
  "facility_name": "140 Inwoods Close, Parklands"
}

관련 Permission 경합 경고 (11건):

text
service:cupixworks-api ("Duplicate permission" OR "add_permission")
json
{
  "message": "[Permission] Duplicate permission detected, retrying for User(X) on Facility(Y)",
  "class": "Facility",
  "function": "add_permission!"
}

최대 지연(10,800ms) 요청의 특징:

  • 3건의 10,000ms+ 요청은 서로 다른 팀에서 발생 — 특정 팀 데이터 크기와 무관
  • View rendering은 0.06~0.10ms로 무시할 수준
  • Serialization도 0~1ms
  • DB 외 시간(application layer): 3,700~10,400ms — 이 시간이 콜백 체인에서 소비됨

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 동기 콜백 체인 누적 (ES 인덱싱 + 썸네일 다운로드 + 서브모델 생성) DB 시간 240425ms vs 전체 4,10010,800ms 불일치; after_create/after_commit에서 최소 6개 모델 생성 + 각각 ES HTTP 호출; change_thumbnail_job!에서 Google Maps HTTP 동기 호출 코드 확인 — Confirmed
H2 Slow DB queries (N+1 또는 lock contention) Duplicate permission 경고 11건 존재 DB 시간 자체는 240~425ms로 정상 범위; slow query 로그 0건; timeout/deadlock 로그 0건 Rejected
H3 Elasticsearch 클러스터 성능 저하 ap-southeast-2 리전에서 ES 네트워크 왕복 시간이 길 수 있음; geo_point 파싱 에러 다수 ES 에러가 FacilitiesController 요청과 직접 연관 없음; 모든 팀/리전에서 동일 패턴 Rejected
H4 특정 팀의 대량 템플릿으로 인한 복사 지연 citycare 팀 12건 연속 생성 arcadis01, scs-assetfuture도 동일하게 10,800ms 기록; 팀 무관하게 최소 4,100ms Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  1. Google Maps 썸네일 생성을 비동기 worker로 이동 — app/models/concerns/thumbnailable/facility.rb:14

    • after_commit :change_thumbnail_job!이 이미 ThumbnailChangeWorker를 호출하는 change_thumbnail 메서드가 존재하나 (line 16-18), 현재는 change_thumbnail_job!이 직접 HTTP 호출을 수행
    • change_thumbnail_job! 대신 change_thumbnail (worker 방식)을 사용하도록 변경

  2. Default 모델 생성을 비동기로 이동 — app/models/concerns/has_default/facility.rb:8

    • create_default_models를 Sidekiq worker로 분리하여 HTTP 응답 후 처리

단기 개선 (1주 이내)#

  1. Skeleton 템플릿 복사를 비동기화 — app/models/concerns/skeleton/facility.rb:8-9

    • create_default_annotation_layers와 create_default_reviews를 별도 worker로 이동
    • 각 hardcopy 호출이 자체 ES 인덱싱을 트리거하므로 지연이 배수로 증가

  2. ES 인덱싱 배치 처리 — app/models/concerns/searchable.rb:34-53

    • Facility 생성 시 서브모델(Level, WorkareaGroup 등)의 개별 _index_document 호출 대신 BulkIndexWorker를 활용한 배치 인덱싱 검토

장기 개선 (재발 방지)#

  1. Facility 생성 응답을 "생성됨" 상태로 즉시 반환하고, 후속 초기화(default models, skeleton, thumbnail)는 모두 비동기 파이프라인으로 처리
  2. after_create/after_commit 콜백 감사 — 모든 모델에서 HTTP 외부 호출이 동기적으로 실행되는 패턴을 식별하고 worker로 전환
  3. ap-southeast-2 리전의 ES 클러스터가 타 리전 대비 지연이 큰지 모니터링 추가

Monitoring#

  • APM P95/P99 latency 알림: FacilitiesController#create 응답 시간이 3,000ms 초과 시 알림
  • 콜백 실행 시간 계측: 주요 after_create 콜백별 실행 시간 로깅 추가
text
service:cupixworks-api resource_name:"Api::V1::FacilitiesController#create" @duration:>3000
text
service:cupixworks-api "[Thumbnail][Facility]" "change_thumbnail_job!"

Risk Assessment#

  • Risk level: medium
  • 예상 복잡도: standard — 기존 ThumbnailChangeWorker와 BulkIndexWorker 패턴이 이미 존재하므로 동일 패턴을 다른 콜백에 적용하면 됨