RCA: Api::V1::RoomsController#create latency (avg 49713ms)

Overview#

What Happened#

2026-07-10 16:49 KST경 ap-southeast-2 production 환경에서 POST /api/v1/rooms (Api::V1::RoomsController#create) 요청이 약 49.7초 동안 처리됨. 동일 시각에 같은 built 테넌트의 Capture#81421 및 자식 Pano/Asset/Bim 리소스에 대한 다중 write 요청(다른 클러스터 AssetsController#create 125s, BimsController#create_resource 111s)이 동시에 발생하여 InnoDB row-lock 대기열이 길어졌고, Rooms POST 도 그 lock contention 큐 뒤쪽에서 대기하다 처리된 것으로 관측됨. 요청 자체는 200 으로 성공했으나 총 소요 시간이 사용자 tolerance (SLO 1s) 를 크게 초과.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-10 16:48 KST (07:48:53–55Z) — Facility#18203 에 대해 User(14807) 권한 grant 시 RecordNotUnique 가 다수 발생 (add_permission! warn 16회) — 동일 세션이 동일 facility 에 대해 병렬 write 를 반복하고 있음을 시사.
2. 2026-07-10 16:49 KST (07:49:21.015Z) — 본 클러스터 Api::V1::RoomsController#create sample trace 최초 관측 (avg_duration_ms=49713).
3. 2026-07-10 16:49–16:51 KST (07:49:21–07:51:35Z) — 동일 인시던트로 sibling 클러스터 AssetsController#create (125s), RoomsController#create (본 건), BimsController#create_resource (111s) 가 status board 에 등록됨 (incident id 2026-07-10-svc-cupixworks-api--unknown-2).
4. 2026-07-10 16:51 KST (07:51:27.207Z) — 슬로우 POST /rooms 응답: duration=45876.04ms, db=11515.27ms, HTTP 200. 같은 초에 POST /rooms (14.1s, db 6.6s), PUT /captures/81421, 다수 PUT /panos/…, POST /assets, POST /bims/3566/resources (400, "Duplicate kind: mesh") 도 완료 — 락 큐가 한 번에 해제된 정황.
5. 2026-07-10 16:49 KST (07:49:35.295Z) — status board 자동 해소 (resolved_at).

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::RoomsController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 49713,
  "max_ms": 49713,
  "sample_trace_id": "103694830734669946"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1 (본 클러스터). 동일 인시던트에 sibling 2건.
• 최초 발생: 2026-07-10 16:49 KST
• 최근 발생: 2026-07-10 16:49 KST

Root Cause Summary#

RDS MySQL (ap-southeast-2) 에서 built 테넌트가 Capture#81421 을 편집하는 동안 Pano/Asset/Bim/Room 등 자식 리소스 생성·수정 요청이 병렬로 유입되었고, counter_culture / counter_cache 로 인해 각 자식 write 는 부모 row (Capture, Facility, Record, Level) 를 UPDATE 하며 InnoDB row lock 을 획득해야 함. 그 결과 하나의 부모 row 를 여러 트랜잭션이 대기하는 lock 큐가 형성됐고, sibling 인시던트(AssetsController#create, BimsController#create_resource) 는 락 대기 중 innodb_lock_wait_timeout 에 도달해 502 를 반환하거나 정합성 검사에서 400 을 반환. 본 클러스터의 RoomsController#create 는 같은 lock 큐의 뒤쪽에 놓여 있었고 락을 획득한 뒤 실제 SQL 실행에 11.5s, 대기에 34s 를 사용해 총 45.9s (샘플) 지연됐다. 즉 latency 는 controller/factory 코드 결함이 아니라 동일 부모 row 에 대한 다중 write 세션에서 발생한 DB lock contention 이 root cause.

Technical Analysis#

Code Path#

• Entry: app/controllers/api/v1/rooms_controller.rb:21-25 — RoomFactory#create! 호출 후 super 로 렌더.
• Factory: app/factories/room_factory.rb:5-30 — BimRepository / FacilityRepository show 로 부모 facility 로드, Pundit.policy(...).create? 권한 체크, super (BaseFactory#create!) 호출.
• BaseFactory: app/factories/base_factory.rb:80-141 — self.model.save! 실행. save! 는 트랜잭션 안에서 counter cache 관련 부모 row UPDATE 를 트리거하고, after_commit 콜백에서 후속 side-effect 를 실행.
• Room save 이후 콜백:
  • Searchable#_index_document (app/models/concerns/searchable.rb:34-53) — ES rooms index 동기 write.
  • EntityIndexable#_entity_index_document (app/models/concerns/entity_indexable.rb:160-170) — bim_entities index 동기 write.
  • Permissionable#share_to_creator → add_permission! (app/models/concerns/permissionable.rb:60-71) — room_permissions insert.

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

  super
end

def create!(params = {})
  self.model = ::Room.new
  # ... bim / facility 로 부모 지정 ...
  self.model.facility = self.parent

  raise Cupix::Errors::PermissionDenied.new(code: 'PERM10000', reason: 'Permission denied') unless Pundit.policy(self.current_user, self.parent).create?

  super
end

begin
  self.model.save!
  self.model
rescue Elasticsearch::Transport::Transport::Errors::BadRequest => e
  raise e
rescue NoMethodError => e
  raise Cupix::Errors::System.new(code: 'SYS10003', reason: e.message)
rescue ActiveRecord::RecordInvalid => e
  raise Cupix::Errors::Entity.new(code: 'ENT10005', reason: e.message)
rescue ActiveRecord::ValueTooLong => e
  raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: 'Invalid argument', message: e.message)
rescue Aws::Errors::ServiceError => e
  raise Cupix::Errors::BadGateway.new(code: 'BG10004', reason: e.message)
rescue StandardError => e
  raise e if e.is_a?(Cupix::Errors::BaseError)

  raise Cupix::Errors::System.new(code: 'SYS50000', reason: e.message)
end

ActiveRecord::LockWaitTimeout 은 별도 rescue 가 없어 StandardError 로 잡힌다. lock wait 이 timeout 없이 성공한 경우는 (본 클러스터처럼) 응답 200 으로 되돌아가지만 요청 소요 시간이 innodb_lock_wait_timeout 만큼 늘어난다.

• Failure point (성능 관점): Room#save! 트랜잭션이 아래 사용된 부모 row 의 InnoDB lock 을 대기 → 34s 대기 후 획득. lock 을 잡고 있던 사이드는 sibling Capture#81421 계열 write 세션.

Log Evidence#

Datadog query (재현용):

service:cupixworks-api @duration:>40000

시간범위 2026-07-10T07:47:00Z–07:55:00Z, 발췌:

{"ts":"2026-07-10T07:51:27.207Z","dur":45876.04,"db":11515.27,"msg":"[200] POST /api/v1/rooms (Api::V1::RoomsController#create)"}
{"ts":"2026-07-10T07:51:27.198Z","dur":14141.01,"db":6631.49,"msg":"[200] POST /api/v1/rooms (Api::V1::RoomsController#create)"}
{"ts":"2026-07-10T07:51:29.212Z","msg":"[200] PUT /api/v1/captures/81421 (Api::V1::CapturesController#update)"}
{"ts":"2026-07-10T07:51:27.211Z","msg":"[200] PUT /api/v1/panos/14606472/stitched (Api::V1::PanosController#stitched)"}
{"ts":"2026-07-10T07:51:27.211Z","msg":"[200] POST /api/v1/assets (Api::V1::AssetsController#create)"}
{"ts":"2026-07-10T07:51:27.210Z","msg":"[400] POST /api/v1/bims/3566/resources (Api::V1::BimsController#create_resource)","error":{"reason":"Duplicate kind: mesh","code":"ARG10001"}}

Rooms POST 는 duration=45876ms, db=11515ms — 총 시간의 75% 는 SQL 실행 밖(대부분 lock 대기)에서 소비됐다. 같은 초(07:51:27.2xx) 에 다수 write 요청이 동시에 완료되는 패턴은 InnoDB lock 이 한꺼번에 해제됐음을 시사.

Datadog query (permission contention, 같은 세션의 병렬성 근거):

service:cupixworks-api "18203"

시간범위 2026-07-10T07:47:00Z–07:51:00Z, 발췌 (16건 중 대표):

2026-07-10T07:48:55.841Z warn  [Permission] Duplicate permission detected, retrying for User(14807) on Facility(18203)
2026-07-10T07:48:55.494Z warn  [Permission] Duplicate permission detected, retrying for User(14807) on Facility(18203)
2026-07-10T07:48:54.122Z warn  [Permission] Duplicate permission detected, retrying for User(14807) on Facility(18203)
2026-07-10T07:48:53.840Z info  Flush cached permissions By User for User 14807 on Facility 18203

같은 user 가 같은 facility 에 대해 병렬로 grant 를 시도해 RecordNotUnique 가 반복 발생 — 세션이 다중 요청을 동시 발사하고 있음을 시사. 이 세션이 곧이어 Room/Asset/Bim/Pano write 를 병렬 전송한 것으로 해석 가능. (⚠ Facility 18203 이 본 클러스터의 room 부모인지는 이 로그만으로 확정 불가 — uncertain. sibling RCA 는 hot row 를 Capture#81421 로 지목.)

Datadog query (status board 자동 인시던트):

scope:svc:cupixworks-api::unknown started_at:2026-07-10T07:40:16Z

bun run cli/incident-board.ts for-cluster ca6ef0b7-… 결과에서 2026-07-10-svc-cupixworks-api--unknown-2 에 본 cluster 와 AssetsController#create, BimsController#create_resource, 그리고 또 다른 API 클러스터가 함께 묶여 있음. 다른 sibling RCA (c25d10f8, c9b5537f) 는 Capture#81421 을 hot parent row 로 지목.

Trace ID 검색 (재현 시도):

service:cupixworks-api "103694830734669946"
service:cupixworks-api @dd.trace_id:103694830734669946

두 쿼리 모두 결과 0건 — APM trace 는 존재하지만 log correlation 이 인덱싱되지 않은 상태 (uncertain — 정확한 트랜잭션 흐름은 APM UI 에서 직접 확인 필요).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• RDS InnoDB lock 지표 확인 (cupixworks-api production ap-southeast-2 RDS)
  • SHOW ENGINE INNODB STATUS, performance_schema.data_locks / data_lock_waits 를 07:47–07:52 UTC 구간 스냅샷에서 조회하여 hot row (Capture/Facility/Record/Level) 를 확정. sibling RCA (c25d10f8) 와 동일한 조치가 필요하므로 중복 실행하지 말고 결과를 공유.
  • 근거: 본 클러스터 슬로우 Room POST duration=45876ms, db=11515ms — 대기 시간이 SQL 실행 시간의 3배. 다중 controller 가 같은 초에 완료된 패턴.
• status board scope 재분류 검토 (error-sweeper 저장소)
  • ActiveRecord::LockWaitTimeout / Mysql2::Error::TimeoutError 시그니처가 감지되면 svc:*::unknown 대신 svc:*::db_lock_contention 또는 dep:rds-mysql-<region> 로 승격. 사이드 이펙트로 sibling 클러스터도 자동으로 같은 인시던트로 묶임.

단기 개선 (1주 이내)#

• ActiveRecord::LockWaitTimeout 별도 rescue (app/factories/base_factory.rb:123-140)
  • 현재 StandardError 로 잡혀 Cupix::Errors::System(SYS50000) → 502 로 렌더. 별도 rescue 를 추가해:
    • 클라이언트에 429/503 + Retry-After 로 응답
    • 로그 레벨을 warn 으로 낮춤 (일시 contention 은 error 로 취급하지 않음)
    • Datadog 메트릭(db.lock_wait_timeout.count) 명시적 emit
  • 근거: sibling RCA (c25d10f8) 에도 동일 항목이 도출됨. 본 클러스터는 timeout 에 도달하지 않아 200 이 반환됐지만 UX 저하는 동일.
• APM 상 슬로우 트랜잭션의 부모 row hot spot 시각화
  • resource_name:Api::V1::RoomsController#create @duration:>10000 트레이스에서 sql.query 실행 계획을 확인해 어떤 부모 row 를 UPDATE 중인지 태깅. (tenant, facility.id, capture.id 를 span tag 로 실어 이후 재발 시 즉시 원인 파악)

장기 개선 (재발 방지)#

• counter_culture / counter_cache 의 hot parent contention 완화
  • Capture, Facility, Record, Level 등 자식 write 마다 UPDATE 되는 부모 row 를 counter_culture 의 execute_after_commit (또는 별도 async 워커) 로 늦추는 옵션을 검토. 즉시 정합성이 필요한 view 는 read-side 집계로 대체.
  • 근거: 단일 캡처를 다중 클라이언트가 동시 편집할 때 부모 row lock 이 병목. 해당 tenant 는 실사용 패턴상 동시 편집이 발생함이 이미 확인됨.
• write 세션 병렬성 정책
  • 프런트엔드/agent 측에서 같은 Capture 에 대한 write batch 를 직렬화하거나, backend 에 write_lock(scope: capture_id) 큐를 두어 lock 큐 depth 를 예측 가능하게 만듦. (프런트엔드/agent 협의 필요 — code-fix 자동 반영 대상 아님.)

Monitoring#

• RoomsController#create p99 latency

  textCopy

  avg:trace.rails.request.duration.by.resource_service.99p\{resource_name:api::v1::roomscontroller#create,service:cupixworks-api\}
  

• API 전반의 InnoDB lock wait 신호 (log 파생)

  textCopy

  service:cupixworks-api ("Lock wait timeout" OR "LockWaitTimeout" OR "ActiveRecord::LockWaitTimeout")
  

• 동일 tenant 의 동시 write 밀집도 지표 (log 파생)

  textCopy

  service:cupixworks-api @tenant:cupix @duration:>10000 (POST OR PUT)
  

• 참고 alert 임계값: 위 3종 로그가 5분 이내 10건 이상이면 즉시 status-board 로 svc:cupixworks-api::db_lock_contention 인시던트를 여는 룰을 error-sweeper 에 추가.

Risk Assessment#

• Risk level: medium — 본 클러스터는 200 응답이었으나 sibling AssetsController#create (125s), BimsController#create_resource (111s / 400) 로 볼 때 동일 세션에서 502/400 을 관측했을 가능성이 크며, 재발 시 UI freeze 및 데이터 정합성 혼란 발생 위험.
• 예상 복잡도: standard — 즉시 조치는 DB 지표 확인(운영성), 단기 개선은 base_factory rescue 분기 추가(단순), 장기 개선은 counter_culture 정책 변경(설계 검토 필요).