ES /docs

BimRevisionsController#create — sequential network I/O in after_create callback

RCA: BimRevisionsController#create Latency (1543ms)

Overview#

What Happened#

2026-05-26 04:23:26 UTC에 cupixworks-api의 Api::V1::BimRevisionsController#create 엔드포인트가 1543ms 응답 시간을 기록했다. ap-southeast-2 리전의 nswgov tenant에서 BIM revision 생성 시 발생한 latency 이슈로, after_create 콜백에서 실행되는 동기적 외부 서비스 호출(SQS, Kinesis)과 세션 생성 오버헤드가 원인이다.

Quick Facts#

Field Value
resource_name Api::V1::BimRevisionsController#create
top_frame app/models/concerns/forge_translatable/bim_revision.rb:23
duration 1543ms (db: 135ms, app: 1406ms, view: 0.06ms)
env production, ap-southeast-2
deploy production-ap-southeast-2-20260523t2205z0-3e770a15-cupixworks
tenant nswgov (team domain: sinsw)

Timeline#

  1. 2026-05-26T04:23:26Z — BimRevision create 요청 수신 (revision name: "V1")
  2. 2026-05-26T04:23:29Z — 응답 완료 (1541ms duration, HTTP 200)
  3. 2026-05-26T04:23:29Z — Forge meta version 업데이트 (후속 PUT 요청)

Error Log#

Datadog Logs

json
{
  "resource_name": "Api::V1::BimRevisionsController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 1543,
  "max_ms": 1543,
  "sample_trace_id": "1937998199677834212"
}

Impact#

  • Service: cupixworks-api
  • 발생 횟수: 1 (단일 이벤트이나 시스템적 패턴의 일부)
  • 최초 발생: 2026-05-26T04:23:26.091Z
  • 최근 발생: 2026-05-26T04:23:26.091Z
  • 패턴: 지난 14일간 BimRevisionsController#create의 평균 응답 시간이 800-1500ms로 일관되게 높음. V1 revision 생성 시 특히 심각 (1000-1500ms).

Root Cause Summary#

BimRevisionsController#create의 after_create 콜백 체인에서 3개의 동기적 네트워크 I/O 호출이 순차적으로 실행되어 응답 시간이 누적된다: (1) agent_team_session 조회/생성 + AWS SQS send_message (ForgeTranslateAgent), (2) AWS Kinesis put_records! (EventService), (3) Elasticsearch HTTP index 요청 (Searchable after_commit). 이 특정 요청에서는 기존 agent session이 없어 SessionFactory.create!로 새 세션을 생성했으며, 이로 인해 DB 시간이 135ms (일반적 ~50ms)로 증가했다. ap-southeast-2 리전에서의 AWS 서비스 엔드포인트 RTT가 추가적으로 누적되었다.

Technical Analysis#

Code Path#

  • Entry point: app/controllers/api/v1/bim_revisions_controller.rb:88
  • Factory 생성: app/factories/bim_revision_factory.rb:5-16
  • Model save: app/factories/base_factory.rb:124
  • after_create callback: app/models/concerns/statable/bim_revision.rb:10 → after_create_with_bim_source
  • State machine transition: app/models/concerns/statable/bim_revision.rb:70-76
  • Forge translate (SQS): app/models/concerns/forge_translatable/bim_revision.rb:23-28
  • Event publish (Kinesis): app/models/concerns/eventable/events/base.rb:7-18
  • ES index (after_commit): app/models/concerns/searchable.rb:34-53

1단계: after_create → state machine transition (동기적)

app/models/concerns/statable/bim_revision.rb:274-279ruby
def after_create_with_bim_source
  if bim_source == 'cupix'
    self.fire_events!(:forge_translation_ready_state)
  else
    self.fire_events!(:translation_skipped_forge_state)
  end
end

bim_source가 'cupix'(기본값)이면 forge_translation_ready_state가 fire되어 아래 state machine after_transition이 실행된다:

app/models/concerns/statable/bim_revision.rb:70-76ruby
after_transition from: any, to: :forge_translation_ready do |bim_revision, transition|
  bim_revision.bim.reset_room_state
  bim_revision.bim.reset_mesh_state
  bim_revision.forge_translate!
  bim_revision.fire_events(:translating_forge_state)
  bim_revision.fire_events(:forge_translating_state)
end

2단계: forge_translate! — SQS 메시지 전송 (동기적 네트워크 I/O)

app/models/concerns/forge_translatable/bim_revision.rb:23-28ruby
def forge_translate!(validate: true)
  check_forge_translatable if validate
  session = self.user.agent_team_session(self.team)
  client = Cws::ForgeTranslateAgent::Client.new(model: self, session: session)
  self.queued_forge_state!
  client.invoke!
end

agent_team_session은 기존 세션을 DB에서 조회하고, 없으면 SessionFactory.create!로 새로 생성한다. client.invoke!는 AWS SQS에 동기적으로 메시지를 전송한다:

lib/cws/base_client.rb:46-59ruby
def invoke!
  raise Cupix::Errors::Argument.new(code: 'ARG10000', reason: 'Session not set') if @session.blank?
  raise Cupix::Errors::Argument.new(code: 'ARG10000', reason: 'Model not set') if @model.blank?

  res = sqs_client.send_message(
    message_body: sqs_body.to_json,
    message_attributes: datadog_message_attributes,
    queue_url: agent_queue_url
  )
rescue StandardError => e
  raise e
else
  res
end

3단계: Event publish — Kinesis put_records (동기적 네트워크 I/O)

app/models/concerns/eventable/events/base.rb:7-18ruby
def create_event(model)
  return nil if invalid_event?(model)

  begin
    event = _create_event(model)
    reason = extract_reason(event, model)
    properties = build_properties(model)

    track_event(model, reason, properties)

    Cupix::EventService.publish_event([event])
    Cupix::Event.publish(event.serializable_hash(stringify_nested_fields: false))
  rescue StandardError => e
    Cupix::Logger.error("Failed to create event: #{e.message}", ...)
    raise e
  end
end
lib/cupix/event_service.rb:21-44ruby
def self.publish_event(events = [])
  # ...
  response = Cupix::Aws::Kinesis.put_records!({ stream_name: stream_name, records: records })
end

4단계: Elasticsearch index (after_commit, 동기적 HTTP)

app/models/concerns/searchable.rb:34-53ruby
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))

  if (tmp_index = self.class.fetch_tmp_index_name)
    __elasticsearch__.client.index(base_request.merge(index: tmp_index))
  end
rescue StandardError => e
  BulkIndexWorker.perform_async(self.class.name, [id], 'index')
end

Log Evidence#

검색 쿼리:

text
service:cupixworks-api "BimRevisionsController#create"
Time range: 2026-05-26T04:23:00Z to 2026-05-26T04:24:00Z

해당 요청의 상세 로그:

json
{
  "duration": 1541.35,
  "db": 135.15,
  "view": 0.06,
  "action": "create",
  "controller": "Api::V1::BimRevisionsController",
  "tenant": "nswgov",
  "team": { "domain": "sinsw", "id": 4 },
  "user": { "firstname": "Eva", "id": 26, "email": "eva.revina@cupix.com" },
  "http": { "status_code": 200, "method": "POST" },
  "host": { "name": "ip-10-1-80-92.ap-southeast-2.compute.internal" },
  "request_id": "5238758a-e71d-4cda-a7c1-748309ffa972",
  "params": { "name": "V1" }
}

지난 14일간 동일 엔드포인트의 duration 분포:

text
service:cupixworks-api "BimRevisionsController#create"
Time range: now-14d to now

V1 revisions (first revision): 818-1541ms (avg ~1100ms)
V2+ revisions: 359-883ms (avg ~550ms)

Duration breakdown:
  2026-05-26T04:23:29Z | dur=1541ms | db=135ms | app=1406ms | tenant=nswgov (V1)
  2026-05-26T04:43:03Z | dur=883ms  | db=37ms  | app=845ms  | tenant=cupix  (V12)
  2026-05-26T04:42:51Z | dur=833ms  | db=39ms  | app=794ms  | tenant=cupix  (V13)
  2026-05-26T01:12:14Z | dur=1123ms | db=66ms  | app=1057ms | tenant=nswgov (V1)
  2026-05-25T21:42:24Z | dur=359ms  | db=39ms  | app=320ms  | tenant=cupix  (V4)

V1 create 시 DB 시간이 높은 이유 — Salesforce case sender 로그에서 확인:

text
service:cupixworks-api status:warn "BimRevision"
Time range: 2026-05-26T03:00:00Z to 2026-05-26T05:30:00Z
json
{
  "timestamp": "2026-05-26 13:23:27 KST",
  "status": "warn",
  "message": "sf_resource_id not exist. skip sending web to case. - case_type: 'bim_upload_case' model: 'BimRevision' model_id: '137'",
  "class": "Cupix::Salesforce::Case::CaseSender",
  "function": "send_web_to_case_in_worker"
}

이 warn 로그는 BimRevision ID 137 생성 직후 Salesforce case 생성 시도가 있었음을 보여준다. 이 또한 동기적 콜백 체인의 일부이다.

Hypotheses Considered#

# Hypothesis Evidence for Evidence against Verdict
H1 after_create 콜백의 동기적 외부 서비스 호출(SQS, Kinesis, ES) 누적이 원인 duration 1541ms 중 db=135ms, app=1406ms로 대부분 app 시간. 코드상 forge_translate! → SQS, EventService.publish_event → Kinesis, _index_document → ES가 모두 동기적 — Confirmed
H2 V1 revision에서 session 부재로 인한 SessionFactory.create! 추가 오버헤드 이 요청 db=135ms (V1) vs 동일 사용자 후속 요청 db=37-39ms (V12/V13). V1은 첫 번째 BIM revision이므로 agent session이 존재하지 않을 가능성 높음 세션 생성 단독으로 ~80ms 추가만 설명 가능, 전체 1400ms app time의 일부분 Confirmed (기여 요인)
H3 ap-southeast-2 리전의 높은 네트워크 RTT 모든 요청이 ap-southeast-2에서 발생. AWS 서비스 엔드포인트(SQS, Kinesis, ES)와의 통신에서 개별 100-300ms RTT가 누적됨 us-west-2 비교 데이터 없음 (BimRevision create는 AU에서만 발생) Confirmed (기여 요인)
H4 단발성 네트워크 지연 또는 AWS 서비스 장애 1541ms가 다른 V1 create (818-1257ms) 대비 약간 높음 14일간 모든 V1 create가 일관되게 800-1500ms. 특정 시점의 장애 증거 없음 Rejected
H5 DB 쿼리 자체의 슬로우 쿼리 db=135ms로 일반적(~50ms)보다 높음 135ms는 전체 1541ms의 9%에 불과. 주요 원인이 아님 Rejected

Fix Recommendation#

즉시 조치 (Critical)#

  • 해당 사항 없음 — 기능적 오류가 아닌 latency 이슈. 사용자 요청은 HTTP 200으로 정상 완료됨.

단기 개선 (1주 이내)#

  • app/models/concerns/forge_translatable/bim_revision.rb:25-28: forge_translate! 내의 SQS send_message를 background worker로 이동. after_create 콜백에서 직접 SQS를 호출하는 대신 Sidekiq job으로 위임하여 응답 시간에서 제거.
  • app/models/concerns/eventable/events/base.rb:17: Cupix::EventService.publish_event의 Kinesis put_records! 호출을 비동기화. 이벤트 발행 실패가 BIM revision 생성 성공 여부에 영향을 주면 안 됨.

장기 개선 (재발 방지)#

  • after_create 콜백 체인 전체를 리뷰하여 HTTP 응답에 영향을 주는 동기적 외부 호출을 식별하고 비동기화. 특히 create 액션에서는 DB save 이후의 side effect를 after_commit + background job 패턴으로 전환.
  • Elasticsearch indexing (searchable.rb:43)도 동기 HTTP 대신 항상 BulkIndexWorker로 위임하는 방안 검토.
  • agent_team_session 캐싱: 세션이 자주 재생성되지 않도록 TTL이나 캐시 레이어를 도입하여 DB 왕복을 줄인다.

Monitoring#

  • BimRevisionsController#create의 p95/p99 duration 모니터링
  • Datadog APM에서 해당 resource의 breakdown 추적
text
avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::bimrevisionscontroller#create,env:production} by {region}
  • SQS send_message 및 Kinesis put_records latency 메트릭:
text
avg:aws.sqs.sent_message_size{queuename:*forge*} by {region}
p95:aws.kinesis.put_records.latency{*} by {region}

Risk Assessment#

  • Risk level: low (기능적 오류 없음, 응답 성공)
  • 예상 복잡도: standard (콜백 비동기화는 기존 worker 인프라 활용 가능하나 state machine transition 순서에 영향 없도록 주의 필요)