RCA: Api::V1::BimsController#grid_system_upload_url (avg 15441ms, max 15441ms)

Overview#

What Happened#

2026-06-26 10:01 KST(ap-southeast-2)에서 POST /api/v1/bims/3545/grid_system_upload_url 요청 한 건이 15.4초 동안 실행된 뒤 HTTP 200으로 정상 응답했다. 에러는 발생하지 않았으며 cluster_type은 latency. 동일 trace_id에서 응답 직전·직후에 같은 Bim(3545)을 대상으로 update, update_meta, check_grid_system_uploading, check_resource_uploading, create_resource 등 다수 PUT/POST가 짧은 간격으로 호출된 BIM 업로드 워크플로 중 한 단계였다.

Quick Facts#

Affected Teams#

영향 범위는 1건이며, 같은 시점 같은 service에서 다른 grid_system_upload_url 호출은 정상 시간 내(POST /api/v1/bims/3544/grid_system_upload_url 2026-06-26 09:27 KST) 완료되었다.

Timeline#

1. 2026-06-26 10:00:14 KST — 동일 클라이언트가 GET /api/v1/bims/3545 수신, BIM 업로드 워크플로 시작
2. 2026-06-26 10:01:55 KST — PUT /api/v1/bims/3545 (직전 update, 200) — 본 span의 약 1초 전
3. 2026-06-26 10:01:54.928 KST — POST /api/v1/bims/3545/grid_system_upload_url span 시작 (first_seen)
4. 2026-06-26 10:02:10 KST — PUT /api/v1/bims/3545/check_grid_system_uploading 200 (병렬/직후 요청)
5. 2026-06-26 10:02:12 KST — grid_system_upload_url 200 응답 (총 ~15.4s 소요)
6. 2026-06-26 10:02:12 KST — PUT /api/v1/bims/3545/meta 200

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::BimsController#grid_system_upload_url",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 15441,
  "max_ms": 15441,
  "sample_trace_id": "4221186551154993054"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-06-26 10:01 KST
• 최근 발생: 2026-06-26 10:01 KST

p99 외 한 건의 극단 latency 이며 동일 endpoint에서 다른 호출은 즉시 완료된다. 사용자 영향은 BIM 업로드 UX에서 약 15초 대기.

Root Cause Summary#

POST /grid_system_upload_url는 presigned URL 생성만 수행하는 가벼운 endpoint처럼 보이지만 실제 호출 그래프는 다음 작업을 동기적으로 수행한다: ① set_bim (BimRepository#show, permission_joins 17 LEFT JOIN 포함) → ② @model.uploading_grid_system_state 호출로 인한 state machine save → ③ Bim 모델에 mix-in 된 30+ concern들의 after_update 콜백 사슬 (EntityUpdates::Child#reset_parent_cached_entity_updates는 매번 ObjectSpace.each_object(Class) 전체 스캔을 실행, Eventable::Callbacks는 동기적으로 Event 레코드를 INSERT + ES _update_document 실행, pub/sub publish 동기 실행) → ④ BimSerializer 렌더 시 grid_system_download_url, grid_system_upload_url, upload_url 등 attribute 계산 + 30+ Attribute concern (Permission/Thumbnail/Storage 등) 로 인한 N+1 가능성. 본 사례는 동일 클라이언트가 같은 Bim(3545)에 대해 짧은 간격으로 수많은 PUT/POST를 연쇄 발사하던 워크플로 중 (10:00:14 ~ 10:02:12 KST 사이 동일 Bim에 13개 요청 관측) 한 요청이 이 동기 콜백 체인 어딘가 (가장 유력한 후보: Eventable::Events::Update.create_event 의 events.sys MEDIUMTEXT TEXT 직렬화 또는 ES _update_document 타임아웃 → Searchable rescue 대기, 또는 동일 row에 대한 InnoDB lock wait) 에서 15초 정도 정체된 결과이다. 단일 occurrence + 200 응답이라는 신호는 에러가 아닌 동기 콜백 사슬에서의 tail-latency 누적을 가리킨다.

Technical Analysis#

Code Path#

진입 → repository.show → state save (heavy after_update chain) → serializer render.

class Api::V1::BimsController < Api::V1::ApiController
  ...
  before_action :set_bim, except: %i[index create create_forge_access_token untrash purge forge_translation_finished_callback mock]
  ...
  include GridSystemController

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

def grid_system_upload_url
  case @model.grid_system_state_name
  when :created, :none, :uploaded
    @model.uploading_grid_system_state   # ← state_machine event, default action :save
  end

  @model
end

uploading_grid_system_state는 state_machine gem이 정의한 transition method이며, AR 모델에서 default action은 :save. 따라서 @model.save 가 실행되어 아래 after_update 콜백 사슬 전체가 동기 실행된다.

class Bim < ApplicationRecord
  include BuildingEntity
  include EntityIndexable
  include Resourcable::Bim
  include ::Statable::Bim
  include ::Cyclable::Bim
  ...
  include ::Eventable::Bim       # after_update → Eventable::Events::Update.create_event
  include EntityUpdates::Child   # after_update → reset_parent_cached_entity_updates
  include GridSystem

included do
  include ::EntityUpdates

  after_create :reset_parent_cached_entity_updates
  after_update :reset_parent_cached_entity_updates
  ...
end

def reset_parent_cached_entity_updates
  self.class.parent_classes.each do |class_name|
    Cupix::Logger.info("reset #{class_name} (ID: #{self.send("#{class_name.underscore}_id")}) cached entity updates", ...)
    Rails.cache.delete(entity_updates_cache_key(class_name, self.send("#{class_name.underscore}_id")))
  end
end

def parent_classes
  Cupix::Loader.load
  ObjectSpace.each_object(Class).select do |model|
    model.superclass == ApplicationRecord && !model.name.include?('::') && !model.name.ends_with?('Permission') && model.respond_to?(:entities) && model.entities.include?(self.name.underscore.to_sym)
  end.map(&:name)
end

ObjectSpace.each_object(Class)는 VM 내 모든 Class 객체를 순회하는 매우 비싼 호출이다. tesla처럼 수천 개 클래스가 로드된 Rails 앱에서 한 번 호출마다 수십 ms 수준의 비용이 누적되며, 직렬 후속 콜백과 합쳐지면 tail latency를 폭발시키는 주범 후보가 된다.

before_update do |model|
  if model.event_params.nil?
    build_event({ action: 'update' })
  end
end

after_update do |model|
  Eventable::Events::Update.create_event(model) if model.event_creation_on_update?
end

Eventable::Events::Update.create_event는 별도의 events 레코드를 INSERT 하며, events.sys는 다른 메모리(memory/services/cupixworks-api.md 기록 참고)에서 TEXT → MEDIUMTEXT 마이그레이션(db/migrate/20260624013858_change_events_sys_to_mediumtext.rb)이 6/24에 적용된 테이블이다. 직렬화 payload가 큰 Bim의 경우 추가 디스크/네트워크 I/O가 동기 경로에 추가된다.

attribute :upload_url do |bim, params|
  if %i[created uploading missing].include?(bim.resource_state_name)
    bim.resource_upload_url
  else
    nil
  end
end

include StorageAttribute
include WorkspaceAttribute
include ThumbnailAttribute
include PermissionAttribute
...
include GridSystemAttribute
include ForgeTranslatableAttribute

GridSystemAttribute는 렌더 시점에 grid_system_download_url / grid_system_upload_url (S3 presigned, 로컬 서명 작업이지만 매 attribute 호출마다 S3 SDK signer를 초기화), Permission/Thumbnail/Storage 등 추가 N개의 attribute concern이 mix-in 되어 N+1 association 호출이 가능한 구조다.

def object(storage_option: nil, **kwargs)
  opts = parse_storage_option(storage_option).merge(kwargs)
  opts[:force_path_style] = true

  check_required_params(opts, %i[region bucket_name key])

  Aws::S3::Object.new(opts)
end

presigned_url 자체는 네트워크 round-trip이 없는 SigV4 서명 작업이므로 단일 호출로 15초가 걸릴 수는 없다. 즉 latency 주범은 이 endpoint에서 추가로 일어나는 동기 콜백 사슬이며, presign 자체가 아니다.

기대 동작 vs 실제 동작:

• 기대: grid_system_upload_url는 state를 uploading으로 변경하고 presigned PUT URL을 반환하는 "가벼운" endpoint. 100~300 ms 이내 응답.
• 실제: state save가 30+ concern의 after_update 콜백을 직렬로 실행 → 그 중 한 단계(가장 가능성 높은 후보: ObjectSpace.each_object(Class) 비용 + Eventable::Events::Update INSERT + Searchable#_update_document ES 호출(10 s timeout) + 동일 Bim row에 대한 lock wait)가 누적/블로킹 되어 15.4 s 소요.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "grid_system_upload_url"
time range: 2026-06-26T00:00:00Z to 2026-06-26T01:30:00Z

service:cupixworks-api ("/bims/3544" OR "/bims/3545")
time range: 2026-06-26T00:55:00Z to 2026-06-26T01:10:00Z

service:cupixworks-api status:error
time range: 2026-06-26T00:55:00Z to 2026-06-26T01:10:00Z

핵심 로그 (요청 본인 + 같은 trace 내 인접 요청):

2026-06-26 10:02:12  info  [200] POST /api/v1/bims/3545/grid_system_upload_url (Api::V1::BimsController#grid_system_upload_url)
2026-06-26 10:02:12  info  [200] PUT  /api/v1/bims/3545/meta (Api::V1::BimsController#update_meta)
2026-06-26 10:02:11  info  [200] PUT  /api/v1/bims/3545 (Api::V1::BimsController#update)
2026-06-26 10:02:11  info  [200] PUT  /api/v1/bims/3545/resources/mesh/check_uploading (Api::V1::BimsController#check_resource_uploading)
2026-06-26 10:02:10  info  [200] PUT  /api/v1/bims/3545/check_grid_system_uploading (Api::V1::BimsController#check_grid_system_uploading)
2026-06-26 10:02:10  info  [200] PUT  /api/v1/bims/3545 (Api::V1::BimsController#update)
2026-06-26 10:01:58  info  [200] POST /api/v1/bims/3545/resources (Api::V1::BimsController#create_resource)
2026-06-26 10:01:58  info  [200] POST /api/v1/bims/3545/resources/mesh/upload_credentials
2026-06-26 10:01:55  info  [200] PUT  /api/v1/bims/3545 (Api::V1::BimsController#update)

응답 시각(10:02:12)과 cluster first_seen (10:01:54.928) 차이 ≈ 17.07s. first_seen은 Datadog APM span 시작 시각으로 avg_duration_ms = 15441 ms와 부합 (작은 차이는 span 종료 후 응답까지의 미들웨어 비용).

이 워크플로에서 동일 Bim(3545)에 대해 2분 내 13개 요청이 발사되었음을 확인 (10:00:14 ~ 10:02:12 KST). 다른 모든 요청은 정상 시간 내 완료, grid_system_upload_url만 15.4s.

같은 시간 창의 에러 로그(status:error)는 본 endpoint와 무관:

2026-06-26 10:08:50  error  Exception occurred at set_upload_state. from: created, to: upload_done, state_updated_at:
2026-06-26 10:08:42  error  processing 'facility_permission.full_permission_enabled' failed: private method `service_jwt' called for class Cupix::NotificationService

두 로그 모두 본 trace보다 6분 뒤이며, class는 Cupix::PubSub::Subscribers::UserRecipeGenerator — 본 endpoint 경로 밖이다.

요청 자체가 success(HTTP 200) 이므로 error 레벨 로그는 발생하지 않았고, span 내부의 단계별 시간 분해는 APM 트레이스(상기 Datadog URL)에서만 직접 확인 가능하다. uncertain -- needs verification: APM 화면에서 어떤 sub-span(activerecord.save, elasticsearch.index, rails.cache.delete 등)이 가장 큰 비중을 차지하는지 확인해야 정확한 hot frame이 특정된다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• APM span 분해 확인 (관측): Datadog APM 화면에서 trace_id 4221186551154993054 의 자식 span(activerecord.save, elasticsearch.index, rails.cache.delete, aws.s3.*) duration을 확인하여 dominant frame 식별. 코드 변경 전에 반드시 어떤 단계가 hot인지 확정한다.
• 단기 Mitigation 후보 — 코드 변경 없음: grid_system_upload_url 클라이언트 측 retry/타임아웃 정책 점검. 단일 occurrence 이므로 코드 변경을 곧장 권장하지 않는다. 추가 1주일 모니터링 후 재발 시 H1 fix 진행.

단기 개선 (1주 이내)#

• EntityUpdates::Child#parent_classes 캐싱 (app/models/concerns/entity_updates/child.rb:12-18): ObjectSpace.each_object(Class) 결과를 self.class 단위 @@parent_classes_cache ||= ... 로 메모이즈. eager_load 가 끝나면 결과가 불변이므로 매 save 호출마다 전체 VM 스캔할 이유가 없다. 근거: 이 메서드가 cupixworks-api 모든 model after_create/after_update 마다 실행되며 모든 endpoint의 tail latency에 기여한다.
• Eventable::Events::Update.create_event 비동기화 검토 (app/models/concerns/eventable/callbacks.rb:34-36): 다른 latency 사례(memory/services/cupixworks-api.md: "Facility creation callback latency", "Inline user group sync latency")에서 사용한 Sidekiq worker로 IO 콜백 이동 패턴을 동일 적용 가능. Event 레코드 INSERT + (있다면) pub/sub publish 를 EventCreationWorker.perform_async(model_id, model_type, action) 으로 옮기면 grid_system_upload_url 같은 가벼운 endpoint의 tail이 짧아진다. 단, audit 로그 강한 일관성 요구가 있는지 reviewer 확인 필요.
• state 변경 전용 경량 API 검토: uploading_grid_system_state는 state column 한 컬럼만 변경하는데 full save 가 30+ concern 콜백을 발화시킨다. update_column(:grid_system_state, 'uploading') 또는 state_machine 의 action: nil + Bim.where(id:).update_all(grid_system_state: 'uploading', updated_at: Time.current) 패턴으로 콜백 우회 가능. 단, ES re-index/이벤트 기록이 필요하다면 그 측면을 별도 보장해야 한다.

장기 개선 (재발 방지)#

• Bim 모델 콜백 사슬 책임 분리: Bim 은 30+ concern을 include 하며 매 save 시 모든 콜백이 발화한다. 어떤 라이프사이클 이벤트(예: state machine transition)에서 어떤 콜백을 실행할지 명시적으로 제어하는 패턴(예: callback group + record.with_callback_group(:state_change) { save }) 도입 검토.
• state machine save 의 cost 표시: state machine event method가 무거운 save를 트리거함을 코드 상 명시 (yardoc/주석)하여 새 endpoint 작성자가 light endpoint 라 오해하지 않도록 한다.
• Tail latency 모니터링 자동화: 동일 endpoint p99 임계치(예: 5s) 초과 시 자동 Datadog monitor + Slack 알림. 단발성 latency 도 클러스터로 모이도록 error-sweeper 의 latency cluster 룰 유지/강화.

Monitoring#

추가/유지할 메트릭:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::BimsController#grid_system_upload_url}.as_count()

max:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::BimsController#grid_system_upload_url}

p99:trace.rack.request.duration{service:cupixworks-api,resource_name:Api::V1::BimsController#grid_system_upload_url}

sum:trace.activerecord.save{service:cupixworks-api,resource_name:Api::V1::BimsController#grid_system_upload_url}.as_count()

writing-datadog-monitoring-queries 가이드 적용: 모든 쿼리는 reducer prefix(sum/max/p99/avg)와 명시적 service 필터를 포함하고, monitor-only 문법(| stats, count by(...), >threshold) 은 사용하지 않음.

Risk Assessment#

• Risk level: low (단일 occurrence, 200 응답, 외부 의존성 outage 아님)
• 예상 복잡도: standard (Bim 콜백 사슬은 광범위 — 변경 시 회귀 테스트 필요)
• 즉시 코드 변경 비권장. 우선 APM 분해 + 추가 발생 모니터링 1주.