RCA: Api::V1::FloorplansController#create (avg 12523ms, max 12523ms)

Overview#

What Happened#

2026-07-13 14:12 KST 에 cupixworks-api 프로덕션(us-west-2, tenant cupix) 에서 POST /api/v1/floorplans 요청 한 건이 12.5s 동안 실행되어 latency 클러스터로 감지되었다. 요청 자체는 200 으로 성공했으나 duration 이 임계치(>500ms)를 크게 초과했다. 단발성 이벤트이며, 동일 endpoint 의 다른 요청은 정상 시간대에 완료되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-13 14:12:10 KST — POST /api/v1/floorplans 요청 시작 (first_seen, cluster start).
2. 2026-07-13 14:12:12 KST — Floorplan(id=90994) 저장 이후 after_create 콜백 실행: 캐시 무효화, 부모 캐시 리셋, Kinesis 이벤트 발행. 이 시점까지 이미 ~2s 경과.
3. 2026-07-13 14:12:24 KST — [200] POST /api/v1/floorplans 완료 로그. 총 12523ms 소요 후 응답. 이후 재발 없음.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FloorplansController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 12523,
  "max_ms": 12523,
  "sample_trace_id": "1202229949995714008"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-13 14:12:10 KST
• 최근 발생: 2026-07-13 14:12:10 KST

Root Cause Summary#

증거로 확정된 root cause 는 아직 없다 — Datadog log 는 트레이스 안에서 6줄만 남았고 (기록된 로그 이벤트 사이에도 이미 최소 2s 이상 간격이 존재), 12s 대부분이 어디에서 소비되었는지 로그가 침묵한다. 유력한 가설은 Floorplan#after_create 콜백 체인 안의 무거운 작업(Cachable::ReviewLoad 캐시 무효화, EntityUpdates::Child#reset_parent_cached_entity_updates 의 ObjectSpace.each_object(Class) 스캔, EventService.publish_event 의 Kinesis put_records! 호출) 이 직렬로 수행되고 그중 하나가 외부 의존성(Kinesis put_records, Rails.cache 백엔드)의 일시 지연을 만난 것이다. 단발성(1건) 이라는 점에서 코드 결함보다는 외부 의존성의 tail latency + 이를 request 스레드에서 동기로 처리하는 구조 조합으로 판단된다. 최종 확정에는 APM span 세부 정보(trace_id 1202229949995714008 의 span breakdown) 확인이 필요하다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/floorplans_controller.rb:28
• Factory create: app/factories/floorplan_factory.rb:5
• super 호출 시 BaseFactory#create! 로 진입 → self.model.save!: app/factories/base_factory.rb:124
• Model save 이후 Rails 가 등록된 after_create 콜백을 순차 실행:
  • Cachable::ReviewLoad#invalidate_facility_review_cache_on_create: app/models/concerns/cachable/review_load.rb:14
  • EntityUpdates::Child#reset_parent_cached_entity_updates: app/models/concerns/entity_updates/child.rb:22
• Failure/latency suspect: EntityUpdates::Child#reset_parent_cached_entity_updates 및 Cupix::EventService.publish_event

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

  super
end

    self.set_parameters(params)

    begin
      self.model.save!
      self.model

Floorplan#save! 이 성공한 이후, 다음 after_create 콜백들이 request 스레드에서 순차 실행된다:

      class << self
        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
      end
    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

기대 동작: parent_classes 는 정적 정보이므로 상수/메모이제이션에서 즉시 반환되고, 캐시 delete 두어 번으로 수 ms 안에 끝나야 한다. 실제 동작: 매 호출마다 Cupix::Loader.load 로 Zeitwerk::Loader.eager_load_all 을 호출하고 ObjectSpace.each_object(Class) 전체 클래스를 순회한다 (lib/cupix/loader.rb:14). 프로덕션에서 이미 eager-load 되어 있어도 each_object(Class) 자체가 GC 트리거링/비용이 큰 연산이며, 이 콜백이 하나의 트랜잭션 안에서 여러 번(Floorplan + 자식 모델들) 호출되면 latency 스파이크의 재료가 된다.

이후 Kinesis 로 이벤트를 발행한다:

    def self.publish_event(events = [])
      return if events.blank?
      return if %w[development test].include?(Rails.env)
      return unless release_date_by(Rails.env)
      ...
      response = Cupix::Aws::Kinesis.put_records!({ stream_name: stream_name, records: records })
      Cupix::Logger.info("Published event - failed_record_count: #{response.failed_record_count} / #{records.size}", ...)

put_records! 는 request 스레드에서 동기로 AWS Kinesis 를 호출한다. Kinesis tail-latency (throttle, retry, DNS 실패 등) 가 발생하면 그대로 요청 지연으로 전파된다. 기대 동작: 100–500ms; 실제 동작: p99 tail 은 초 단위까지 늘어날 수 있다.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api trace_id:1202229949995714008

해당 trace 의 로그 (Datadog Logs API, 시간 범위 now-24h):

{"timestamp":"2026-07-13 14:12:24","status":"info","message":"[200] POST /api/v1/floorplans (Api::V1::FloorplansController#create)"}
{"timestamp":"2026-07-13 14:12:12","status":"info","message":"reset Facility (ID: 13992) cached entity updates","class":"Floorplan","function":"reset_parent_cached_entity_updates"}
{"timestamp":"2026-07-13 14:12:12","status":"info","message":"Published event - failed_record_count: 0 / 1","class":"Cupix::EventService","function":"publish_event"}
{"timestamp":"2026-07-13 14:12:12","status":"info","message":"No custom groups found for user 10131, tim.son@cupix.com","class":"UserFactory","function":"update_user_groups!"}
{"timestamp":"2026-07-13 14:12:12","status":"info","message":"reset Facility (ID: 13992) cached entity updates","class":"Floorplan","function":"reset_parent_cached_entity_updates"}
{"timestamp":"2026-07-13 14:12:12","status":"info","message":"Cachable::ReviewLoad | Invalidated facility review cache on create | model=Floorplan | model_id=90994 | facility_id=13992"}

주요 관찰:

• 6개 이벤트 모두 14:12:12 초에 몰려 있고, 완료 응답만 12초 뒤인 14:12:24 에 찍혔다. 따라서 12.5s 중 대부분이 마지막 로그(Published event) 이후에 소비되었거나, 그 이전 controller 초기 처리 단계(auth, param parsing, save!) 에서 소비되었다. 로그만으로는 어느 쪽인지 확정 불가 (uncertain -- needs verification).
• reset Facility ... cached entity updates 가 같은 초에 두 번 반복된다. 이는 Floorplan 저장 후 한 번, 그리고 Floorplan 이 소속된 상위 모델(예: level) 저장 시 추가 한 번 트리거된 것으로 보이며, callback overhead 가 반복되고 있음을 시사한다.
• 동시간대(now-4h, @duration:>500ms) 필터로도 이 트레이스만 잡혔고, apm.rack.request.duration timeseries 도 빈 결과였다 (resource_name 태그가 metrics 에는 축적되지 않은 것으로 보임). 재발은 관측되지 않았다.

APM 기간 필터 참고 쿼리:

service:cupixworks-api "FloorplansController#create" @duration:>500ms

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• trace_id 1202229949995714008 의 APM span breakdown 을 확인: Datadog APM UI 에서 실제로 어느 span (DB, Redis, Kinesis, aws.request) 이 12s 중 대부분을 차지했는지 확인해야 root cause 확정 가능. 로그만으로는 확정 불가 (uncertain -- needs verification).
• 확인 파일: app/controllers/api/v1/floorplans_controller.rb:28-32, app/factories/floorplan_factory.rb:5-66.

단기 개선 (1주 이내)#

• EntityUpdates::Child.parent_classes 결과를 클래스 단위로 메모이제이션: app/models/concerns/entity_updates/child.rb:12-19. 매 호출마다 Cupix::Loader.load + ObjectSpace.each_object(Class) 를 수행할 이유 없음. 앱 boot 이후 한 번만 계산해 상수/@@parent_classes 로 저장하면 반복 호출 비용을 실질적으로 제거할 수 있다. 근거: 콜백 흐름 상 모든 after_create/after_update 마다 트리거됨 (entity_updates/child.rb:8-9).
• Cupix::EventService.publish_event 를 fire-and-forget 큐로 이동: lib/cupix/event_service.rb:43 의 put_records! 를 Sidekiq job (또는 별도 스레드/threadpool) 에 위임. 요청 스레드는 이벤트 payload 를 큐에 넣고 즉시 반환하도록 변경. Kinesis 의 tail-latency 가 사용자 요청 시간에 영향을 주지 않도록 분리하는 것이 목적.
• 엔드포인트별 alert 조건 강화: resource_name:"Api::V1::FloorplansController#create" 에 대해 p95>3s 이 5분 동안 지속되면 alert 하도록 monitor 추가.

장기 개선 (재발 방지)#

• after_create / after_commit 콜백 감사(audit): Floorplan 등 자주 생성되는 모델이 include 하는 concern 이 20개 이상. 각 concern 이 request 스레드에서 무엇을 하는지 정리하고 (외부 I/O, ObjectSpace, 대량 SQL), 동기로 남길 것과 async 로 옮길 것을 구분한다.
• ObjectSpace.each_object(Class) 사용처 전반 리팩터링: rake 태스크나 boot 시 한 번만 실행하는 지점(elasticsearch.rake:12, migrate.rake:214, counter_culture.rb:8 등) 은 문제 없지만, request 경로에서 반복 호출되는 지점 (entity_updates/child.rb:15, workspace_entity/facility.rb:24, transferable/descendants.rb:35) 은 반드시 캐싱해야 한다.

Monitoring#

• Floorplan create p95 latency:

p95:trace.rails.request{service:cupixworks-api,resource_name:api::v1::floorplanscontroller#create}

• Kinesis put_records latency (event publish 병목 확인용):

avg:aws.kinesis.putrecords.latency{service:cupixworks-api}

• 12s+ 요청 발생 카운트:

sum:trace.rails.request.hits{service:cupixworks-api,resource_name:api::v1::floorplanscontroller#create,duration:>5s}.as_count()

• p99 request duration timeseries:

p99:trace.rails.request{service:cupixworks-api,resource_name:api::v1::floorplanscontroller#create}

Risk Assessment#

• Risk level: low (단발 1건, 응답은 성공, 사용자 데이터 손실 없음. 다만 재발 시 사용자 경험 저하 가능)
• 예상 복잡도: standard (콜백 캐싱 및 Kinesis 발행 async 화는 별도 spec/모니터링 필요)