RCA: Api::V1::FloorplansController#complete_creation (avg 14962ms, max 14962ms)

Overview#

What Happened#

2026-07-08 21:30 KST 에 cupixworks-api production (us-west-2) 에서 Api::V1::FloorplansController#complete_creation 요청이 14.96초간 지속되었다. 대상 리소스는 team.domain=exyte의 floorplan id 90746 이며, HTTP 상태 200으로 정상 응답했으나 응답 지연이 임계치를 초과해 latency 클러스터로 감지되었다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-08 21:29:53 KST — Floorplan 90745 complete_creation 완료 (2669ms) — 같은 세션에서 연쇄 요청 시작.
2. 2026-07-08 21:30:01 KST — Floorplan 90746 check_uploading 및 update 호출 (정상).
3. 2026-07-08 21:30:03 KST — Floorplan 90746 update_meta_by_key 완료.
4. 2026-07-08 21:30:16 KST — Floorplan 90746 complete_creation 응답 (200), 총 14715ms 소요 (Datadog request log 기준).
5. 2026-07-08 21:30:47 KST — Floorplan 90747 complete_creation 완료 (4620ms) — 지연 회복 조짐 없음, 동일 사용자의 후속 요청도 4초 이상 소요.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::FloorplansController#complete_creation",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 14962,
  "max_ms": 14962,
  "sample_trace_id": "99484605683438107"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-08 21:30 KST
• 최근 발생: 2026-07-08 21:30 KST

Root Cause Summary#

FloorplansController#complete_creation 은 FloorplanRepository#complete_creation → model.complete_creating_state! 를 호출하고, state_machine 의 complete_creating 이벤트는 리소스 상태에 따라 resource_uploaded 또는 done 으로 전이한다. 이 전이의 after_transition 콜백이 요청 스레드에서 동기적으로 외부 시스템 호출을 여러 개 수행한다: update_thumbnail (SQS send_message), translate_model (SQS send_message), 그리고 bim_floorplan? 인 경우 즉시 done_state 를 발화시켜 notify_floorplan_done (DB create_notification_history + Cupix::Mailer::FacilityMailer.update_on_facility + Analytics.track) 을 실행한다. 문제의 요청은 총 14715ms 중 DB 시간은 2327ms 에 불과하고 나머지 ~12.4초가 콜백 체인 내부의 외부 호출(SQS/mailer/analytics)에 사용된 것으로 관측된다. 즉, HTTP 요청 처리 중 다수의 외부 I/O 를 직렬로 대기하는 구조가 근본 원인이다.

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/floorplans_controller.rb:59
• Repository dispatch: app/repositories/floorplan_repository.rb:239
• State machine: app/models/concerns/statable/floorplan.rb:70 (event :complete_creating)
• Callback 1 (resource_uploaded → thumbnail SQS): app/models/concerns/statable/floorplan.rb:11 → app/models/concerns/thumbnailable/agent.rb:30
• Callback 2 (resource_uploaded → floorplan agent SQS): app/models/concerns/translatable/callbacks/floorplan.rb:10 → app/models/concerns/translatable/floorplan.rb:27
• Callback 3 (bim → done_state → mailer+analytics): app/models/concerns/translatable/callbacks/floorplan.rb:11, app/models/concerns/notifiable/floorplan.rb:8

컨트롤러는 얇지만, 모델 콜백 체인이 요청 스레드에서 다수의 외부 I/O 를 순차 수행한다:

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

def complete_creation
  self.model.complete_creating_state!
  self.model
end

event :complete_creating do
  transition creating: :done, if: ->(floorplan) { floorplan.resource_state_uploaded? && floorplan.tile_state_uploaded? }
  transition creating: :created, if: :resource_state_created?
  transition creating: :resource_uploaded, if: :resource_state_uploaded?
  transition creating: :resource_uploading, if: :resource_state_uploading?
  transition creating: :resource_missing, if: :resource_state_missing?
end

after_resource_uploaded_state :update_thumbnail

def update_thumbnail!(validate: true)
  return if self.respond_to?(:soft_copied?) && self.soft_copied?

  check_thumbnail_updatable if validate
  session = self.user.agent_team_session(self.team)
  client = Cws::ThumbnailAgent::Client.new(model: self, session: session)
  update(thumbnail_update_queued_at: DateTime.now)
  client.invoke!
end

included do
  include ::Translatable::Callbacks

  after_create :translate_model, if: :translatable?
  after_resource_uploaded_state :translate_model, if: :translatable?
  after_resource_uploaded_state :done_state, if: :bim_floorplan?
end

def translate_model!(validate: true)
  session = self.user.agent_team_session(self.team)
  client = Cws::FloorplanAgent::Client.new(model: self, session: session)
  update(floorplan_translate_queued_at: DateTime.now)
  client.invoke!
end

after_done_state :notify_floorplan_done

def notify_floorplan_done
  return unless floorplan_done_notifiable?

  creation_from = self.meta['prop']['bimId'] rescue nil
  reason = creation_from.present? ? BIM360_SHEET_DONE : FLOORPLAN_DONE

  self.create_notification_history(reason)
  Cupix::Mailer::FacilityMailer.update_on_facility(self, reason)
  Analytics.track(
    user_id: user.crn,
    event: 'BE_FLOORPLAN_DONE',
    properties: { ... }
  )
end

기대 동작: 상태 전이 후 부수적인 알림/썸네일/번역 요청은 백그라운드 작업으로 위임되어 HTTP 응답은 sub-second 수준이어야 한다.

실제 동작: 하나의 요청 스레드가 sqs_client.send_message (썸네일), sqs_client.send_message (floorplan-agent), 그리고 (bim_floorplan? 이 false 인 image/pdf 계열은) create_notification_history INSERT, Cupix::Mailer::FacilityMailer.update_on_facility (SES/SMTP), Analytics.track (Segment/Analytics HTTP) 를 순차 호출한다. 개별 호출이 수백ms만 소요돼도 합쳐서 10초를 초과할 수 있다.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "complete_creation"

service:cupixworks-api "90746"

같은 사용자 세션의 complete_creation 요청 3건이 모두 정상 응답이지만 소요 시간이 크게 차이난다 — 90746 이 14.7초로 유독 길다:

{
  "@timestamp": "2026-07-08T12:29:53.884Z",
  "path": "/api/v1/floorplans/90745/complete_creation",
  "http.status_code": 200,
  "duration": 2669.91,
  "db": 1086.33
}

{
  "@timestamp": "2026-07-08T12:30:16.988Z",
  "path": "/api/v1/floorplans/90746/complete_creation",
  "http.status_code": 200,
  "duration": 14715.01,
  "db": 2327.48,
  "user": { "id": 39791, "email": "piamaria.nehme@cupix.com" },
  "team": { "id": 783, "domain": "exyte" }
}

{
  "@timestamp": "2026-07-08T12:30:47.033Z",
  "path": "/api/v1/floorplans/90747/complete_creation",
  "http.status_code": 200,
  "duration": 4620.4,
  "db": 1642.33
}

Floorplan 90746 요청의 브레이크다운 — 총 14715ms 중 DB 는 2327ms (16%). 나머지 ~12388ms 는 non-DB 구간(외부 I/O). sample_trace_id: 99484605683438107 이 이 요청의 APM trace 이며 (14962ms 은 APM 스팬, 14715ms 는 Rails request 로그 — 프레임워크 미들웨어 계층에서 소량의 차이 발생).

같은 floorplan 의 선행 요청도 정상적으로 200 응답:

21:30:01 KST — PUT /api/v1/floorplans/90746/check_uploading  (200)
21:30:01 KST — PUT /api/v1/floorplans/90746                   (200, update)
21:30:03 KST — PUT /api/v1/floorplans/90746/meta/prop         (200, update_meta_by_key)
21:30:16 KST — PUT /api/v1/floorplans/90746/complete_creation (200, 14715ms)

• 형제 요청(90747, sibling naming SGOPS-S-DS1-00-BLDG-001.rvt) 도 4.6초로 이미 정상 임계치 초과.
• Status board 상 동일 시간대 활성 인시던트 없음 — 개별 요청의 콜백 체인 소요가 원인.

status board 확인:

scope: svc:cupixworks-api::unknown
active: null
recent: (last 7d, 4 resolved incidents on same scope)

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 없음. 200 응답이며 데이터 손실이나 정합성 문제는 없다. 그러나 사용자 UX(클라이언트 타임아웃 위험, 특히 15초는 ALB/CloudFront idle timeout 근처) 개선을 위해 아래 단기 개선 필수.

단기 개선 (1주 이내)#

• 콜백을 Sidekiq 로 위임: app/models/concerns/statable/floorplan.rb:11 의 after_resource_uploaded_state :update_thumbnail 을 perform_async 계열 워커로 감싸는 얇은 wrapper 로 교체. 팀 컨벤션상 Thumbnailable::Agent#update_thumbnail 이 이미 rescue StandardError; false 이므로 실패 격리는 유지되나, SQS 호출은 워커로 이동해 요청 응답에서 제외.
• Cupix::Mailer::FacilityMailer.update_on_facility 를 deliver_later 로 전환: app/models/concerns/notifiable/floorplan.rb:19. Rails ActiveJob 큐를 이용하여 HTTP 요청 스레드 밖으로 이메일 발송 이동.
• Analytics.track 을 워커로 이동: app/models/concerns/notifiable/floorplan.rb:21. Segment/analytics 서비스 latency 가 요청 응답에 영향을 주지 않도록 격리.
• 세션 캐싱: self.user.agent_team_session(self.team) 이 콜백 두 번(썸네일/agent) 호출된다면 요청 스코프에서 memoize. 우선 user.agent_team_session 구현을 확인해 이미 캐싱되어 있는지 검증 필요.

장기 개선 (재발 방지)#

• 상태 전이 콜백 정책 문서화 — after_*_state 훅에서는 외부 I/O 를 직접 호출하지 않고 Sidekiq/ActiveJob 위임만 허용하도록 규칙화. 리뷰 checklist 에 반영.
• APM 기반 slow-endpoint 상시 알림 도입 (하단 Monitoring 참조) — 임계치 5초 초과 시 알림.
• complete_creation 엔드포인트 응답을 202 Accepted + 비동기 상태 폴링 패턴으로 재설계 검토. 완료 판정은 별도 상태 조회로 이관하면 초기 응답을 sub-second 로 낮출 수 있다.

Monitoring#

• p95 latency 및 초과 발생 카운트를 추적한다. 아래 쿼리는 release dashboard timeseries widget 에 그대로 사용 가능.

95th percentile 응답 시간 (초 단위):

p95:trace.rack.request{service:cupixworks-api,resource_name:Api::V1::FloorplansController#complete_creation}

5초 초과 요청 발생률:

sum:trace.rack.request.hits{service:cupixworks-api,resource_name:Api::V1::FloorplansController#complete_creation,duration:>5s}.as_count()

동일 controller#action 의 에러율(대조군):

sum:trace.rack.request.errors{service:cupixworks-api,resource_name:Api::V1::FloorplansController#complete_creation}.as_count()

• 임계 제안: p95 > 3000ms, 또는 5초 초과 카운트가 5분 창에서 3회 이상이면 알림.

Risk Assessment#

• Risk level: medium — 200 응답이라 실패는 아니나 15초 지연은 클라이언트 타임아웃 및 UX 저하 유발. 동일 사용자의 다른 요청도 4~5초 근접해 확산 조짐.
• 예상 복잡도: standard — 콜백을 워커/ActiveJob 로 옮기는 국지적 변경. 다만 update_thumbnail 등이 다른 모델(Attachment/Asset)에서도 재사용되므로 회귀 테스트 필수.