RCA: Api::V1::BimsController#create_resource 111.7s latency

Overview#

What Happened#

2026-07-10 16:49–16:51 KST 사이 cupixworks-api (ap-southeast-2)의 Api::V1::BimsController#create_resource 요청 1건이 111.5초 소요된 뒤 [400] Duplicate kind: mesh 로 응답됨. 같은 시간대에 3건의 ActiveRecord::LockWaitTimeout (Mysql2::Error::TimeoutError, 50s) 502 응답과 19건의 60s 초과 write 요청이 관측된 광범위 RDS InnoDB row-lock contention 이벤트의 일부. 대상 요청은 락 큐에 갇혀 있다가 락 해제 후 실행되었고, 그 사이 동일 세션의 선행 요청이 이미 mesh kind Resource 를 생성해 두어 중복 검증에 걸림.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-10 16:47:04 KST — 평시: 동일 세션이 GET/PUT /api/v1/bims/3566 정상 응답.
2. 2026-07-10 16:47:34–16:47:52 KST — BimAiOperation#get 에서 404 no current extraction for bim 7400 8건 발생 (환경은 dev, region us-west-2 — 이 클러스터와 직접 관련 없음, 인과 관계 확인되지 않음).
3. 2026-07-10 16:48:47 KST — 첫 이상 조짐: capture 81421 update 가 39.8s(db 33.4s)로 지연.
4. 2026-07-10 16:49:35 KST — 대상 클러스터 이벤트 시작 (first_seen). 동일 세션에서 POST /api/v1/bims/3566/resources (kind=mesh, name=mesh.zip) 시작. 이 시점 이후 요청은 락 대기 큐에 진입.
5. 2026-07-10 16:50:34 KST — 선행/병렬 요청 POST /api/v1/bims/3566/resources 가 먼저 200 으로 완료되며 mesh kind Resource row 를 생성. 같은 초에 PUT /bims/3566, check_uploading, resource_upload_credentials 도 완료.
6. 2026-07-10 16:51:16–16:51:20 KST — built 테넌트의 세 write 요청이 정확히 50s 만에 Mysql2::Error::TimeoutError 로 502 반환.
7. 2026-07-10 16:51:27.210 KST — 락이 해제되면서 대상 요청이 111,502ms 뒤 find_by_kind(:mesh) 검사에 도달, 이미 생성된 mesh row 를 발견하고 Cupix::Errors::Parameter(ARG10001, "Duplicate kind: mesh") 로 400 반환. 같은 초에 sibling 클러스터 요청들(AssetsController#create 125.5s, RoomsController#create 49.7s) 도 flush.
8. 2026-07-10 16:51:32 KST — capture 81421 update 가 810ms 수준으로 회복 → 인시던트 해소.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::BimsController#create_resource",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 111692,
  "max_ms": 111692,
  "sample_trace_id": "103694830734669946"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 1
• 최초 발생: 2026-07-10 16:49 KST
• 최근 발생: 2026-07-10 16:49 KST

Sibling 클러스터(c25d10f8-… AssetsController#create 125.5s, ca6ef0b7-… RoomsController#create 49.7s, 5a1789e2-…)와 함께 status board 인시던트 2026-07-10-svc-cupixworks-api--unknown-2 (resolved, 2026-07-10T07:40:16Z–07:49:35Z) 로 묶여 있음. 동일 원인의 recent 인시던트 6건(2026-07-03 ~ 2026-07-10) 이 svc:cupixworks-api::unknown scope 로 존재 → 재발 패턴. 실제 사용자 영향은 이 단일 클러스터보다 훨씬 넓음 (같은 창에서 60s+ 지연 요청 19건, 502 응답 3건).

Root Cause Summary#

RDS MySQL (ap-southeast-2) 에서 다중 write 엔드포인트가 동일 부모 row(특히 built 테넌트의 Capture#81421 및 자식 Pano/Asset) 를 대상으로 동시에 UPDATE 를 시도하면서 InnoDB row-lock 대기열이 쌓임 — sibling AssetsController#create RCA 에서 이미 확정된 근본 원인. 이 클러스터의 요청(POST /bims/3566/resources) 은 그 lock contention 큐의 후미에 걸려 82초를 락 대기, 29.5초를 실제 SQL 실행에 소비 (duration=111502.69ms, db=29548.64ms). 대기 도중 동일 세션의 다른 POST /bims/3566/resources (또는 선행 요청) 가 먼저 커밋되어 mesh kind Resource row 가 생성되었고, 대상 요청이 락 획득 후 진입한 MultipleResourcableController#create_resource:53 의 find_by_kind 중복 검사에서 이미 존재하는 row 를 발견해 Cupix::Errors::Parameter(ARG10001) 로 400 을 반환. 즉 latency 자체는 DB lock contention, 400 응답 자체는 client 측 (또는 세션 내부의) 중복/재시도 POST 로 이해할 수 있음.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/bims_controller.rb — Api::V1::BimsController 는 MultipleResourcableController concern 을 include, 라우팅 POST /api/v1/bims/:id/resources 는 create_resource 액션으로 매핑됨.

scope 'resources' do
  get '', action: :index_resource
  post '', action: :create_resource
  get ':kind_or_key', action: :show_resource
  delete ':kind_or_key', action: :destroy_resource

Before-action 체인: bims_controller.rb:9 의 before_action :set_bim (create_resource 는 제외되지 않음) → set_bim 이 BimRepository#show(params[:id]) 로 Bim(3566) 을 로드.

def set_bim
  @model = repository_instance.show(params[:id])
end

추가로 MultipleResourcableController.included do ... before_action :check_kind, only: [:create_resource] 및 set_resource_serializer_option 이 실행됨.

included do
  include CyclableController

  before_action :set_multiple_resource, only: %i[show_resource download_multiple_resource destroy_resource resource_upload_url resource_upload_credentials check_resource_uploading]
  before_action :check_kind, only: [:create_resource]
  before_action :set_resource_serializer_option, only: %i[index_resource show_resource create_resource check_resource_uploading resource_upload_url]
end

Failure(대기) point: app/controllers/concerns/multiple_resourcable_controller.rb:52-63 — 중복 검사 후 resource.save 를 호출. 이 트랜잭션이 resources INSERT 와 함께 bims (updated_at touch) 및 facilities (counter_culture: bims_count) 등 부모 row 를 갱신하며 락을 획득해야 함. 동일 시간대 다른 write 트랜잭션이 부모 row 를 이미 잡고 있으면 최대 innodb_lock_wait_timeout 초까지 대기.

def create_resource
  raise Cupix::Errors::Parameter.new(code: 'ARG10001', reason: "Duplicate kind: #{params[:kind]}") and return unless @model.resources.find_by_kind(params[:kind]).blank?

  resource = @model.resources.new kind: params[:kind],
                                  user: current_user,
                                  team: @model.team,
                                  name: params[:name]

  begin
    unless resource.save
      raise Cupix::Errors::Parameter.new(code: 'ENT10003', reason: resource.errors.full_messages)
    end
  rescue Cupix::Errors::Parameter => e
    raise e
  else
    render_api Renderable.new({
      contents: resource,
      serializer: ResourceSerializer,
      serializer_option: {
        fields: {
          resource: @fields
        },
        is_collection: false
      }
    })
  end
end

주목할 점: find_by_kind 검사 자체가 락을 잡지는 않지만, set_bim 등의 SELECT 쿼리가 트랜잭션에 참여하거나 다른 요청과 동일 튜플에 대한 shared lock 을 기다리며 큐잉될 수 있음.

중복 응답 원인 (400 Duplicate kind): 대기 도중 다른 요청이 먼저 mesh kind Resource 를 생성했음을 로그로 확인.

07:50:34 UTC   200  duration=127.15 ms  db=- ms         (선행 요청, mesh row 생성)
07:51:27 UTC   400  duration=111,502 ms db=29,548 ms    (대상 요청, "Duplicate kind: mesh")

두 요청은 동일 session_id: f66c60830f9f328a00169df8fc54eb26cf9d9565, 동일 user id:8(cupix-agent), 동일 params name: mesh.zip, id: 3566. cupix-agent (자동화 클라이언트) 가 첫 요청 응답 지연 중 재시도했거나 병렬로 두 번 요청한 것으로 추정 — 로그에는 재시도 로직 자체가 남지 않아 uncertain.

Bim 모델의 락 확산 경로: app/models/bim.rb:43-46

include EntityUpdates::Child

belongs_to :user, optional: true
belongs_to :team, optional: true
belongs_to :workspace, optional: true
belongs_to :facility, optional: true
belongs_to :last_bim_revision, optional: true, class_name: 'BimRevision'

counter_culture :facility,
                column_name: proc { |model| model.untrashed? ? 'bims_count' : nil },
                column_names: { ::Bim.untrashed => :bims_count }

• Resource INSERT 트랜잭션이 bims.updated_at touch 를 유발 → facilities.bims_count counter_culture 도 트리거 가능.
• EntityUpdates::Child 는 부모(Facility) cached_entity_updates reset 을 실행 (16:50:36 로그: reset Facility (ID: 4189) cached entity updates).
• 동시에 진행되는 built 테넌트 요청들이 서로 다른 facility 라도 shared indexes/pages 및 innodb metadata lock 을 통해 wait queue 를 형성할 수 있음.

Log Evidence#

사용한 Datadog 쿼리 (시간 범위 2026-07-10T07:40:00Z – 2026-07-10T07:55:00Z):

service:cupixworks-api "Api::V1::BimsController#create_resource" env:production
service:cupixworks-api env:production region:ap-southeast-2 "bims/3566"
service:cupixworks-api env:production "Lock wait timeout"
service:cupixworks-api env:production status:error
service:cupixworks-api status:error

대상 요청 원문 (POST /api/v1/bims/3566/resources, 400):

{
  "@timestamp": "2026-07-10T07:51:27.210Z",
  "controller": "Api::V1::BimsController",
  "action": "create_resource",
  "duration": 111502.69,
  "db": 29548.64,
  "view": 0.17,
  "http": { "status_code": 400, "method": "POST", "url_details": { "path": "/api/v1/bims/3566/resources" } },
  "error": {
    "reason": "Duplicate kind: mesh",
    "code": "ARG10001",
    "message": "Duplicate kind: mesh",
    "class": "Cupix::Errors::Parameter"
  },
  "params": { "name": "mesh.zip", "id": "3566", "fields": ["key","name","kind","size","state","meta","created_at","updated_at","upload_url"] },
  "tenant": "cupix",
  "team": { "domain": "cupix", "id": 6 },
  "user": { "id": 8, "email": "yohan.kim@cupix.com", "firstname": "Cupix", "lastname": "Support" },
  "user_agent": "cupix-agent",
  "session_id": "f66c60830f9f328a00169df8fc54eb26cf9d9565",
  "remote_ip": "54.253.237.17",
  "host": "ip-10-1-147-96.ap-southeast-2.compute.internal",
  "region": "ap-southeast-2",
  "request_id": "98ccc4df-9e46-4381-9cea-8e009b60c6c5"
}

• duration - db = 111502.69 - 29548.64 = ~81,954 ms — 이 시간은 실제 SQL 실행에는 포함되지 않았음. 락 대기, 이후 Ruby-side 렌더/트랜잭션 rollback, 또는 트랜잭션 밖 처리 중 어딘가에서 소비되었으나 로그의 단일 필드로 세분화는 불가 (uncertain — needs verification via APM span).

Bim 3566 관련 시간대 요청 (asc 정렬):

07:47:04 UTC   200  GET  /api/v1/bims/3566                           (평시)
07:47:04 UTC   200  PUT  /api/v1/bims/3566
07:48:28 UTC   200  GET  /api/v1/bims/3566
07:48:30 UTC   200  PUT  /api/v1/bims/3566
07:48:47 UTC   200  GET  /api/v1/bims/3566
07:48:47 UTC   200  PUT  /api/v1/bims/3566
07:50:14 UTC   200  POST /api/v1/bims/3566/grid_system_upload_url
07:50:14 UTC   200  PUT  /api/v1/bims/3566/check_grid_system_uploading
07:50:14 UTC   200  POST /api/v1/rooms                                (같은 flush wave)
07:50:14 UTC   200  PUT  /api/v1/bims/3566/meta
07:50:14 UTC   200  PUT  /api/v1/bims/3566
07:50:34 UTC   200  POST /api/v1/bims/3566/resources                  (선행 mesh 생성)
07:50:34 UTC   200  POST /api/v1/bims/3566/resources/mesh/upload_credentials
07:50:34 UTC   200  PUT  /api/v1/bims/3566/resources/mesh/check_uploading
07:50:34 UTC   200  PUT  /api/v1/bims/3566
07:51:27 UTC   400  POST /api/v1/bims/3566/resources                  (target 111.5s, Duplicate kind: mesh)

같은 시간대 502 LockWaitTimeout (production, ap-southeast-2):

07:51:16 UTC   [502] PUT /api/v1/assets/ze125xzhp1dz            (AssetsController#update)
07:51:18 UTC   [502] PUT /api/v1/panos/14606467/check_tile_uploading
07:51:20 UTC   [502] PUT /api/v1/captures/81421                 (CapturesController#update)

• 각 요청의 error: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (ActiveRecord::LockWaitTimeout).
• db 값이 정확히 ~50,180 ms → innodb_lock_wait_timeout=50s 기본값과 일치.
• 이 세 요청은 모두 built 테넌트(team 16), user_agent cupix-agent. 대상 클러스터 요청과 동일 host ip-10-1-147-96.ap-southeast-2.compute.internal 에서 처리된 것들도 포함 — DB(공유 자원) 문제이지 특정 앱 인스턴스 이슈가 아님.

Status board 인시던트 (자동 감지된 클러스터 그룹):

id:             2026-07-10-svc-cupixworks-api--unknown-2
scope:          svc:cupixworks-api::unknown
status:         resolved
started_at:     2026-07-10T07:40:16.818Z
resolved_at:    2026-07-10T07:49:35.295Z
cluster_ids:    5a1789e2-…, ca6ef0b7-…, c25d10f8-…, c9b5537f-… (this)

동일 scope 로 최근 7일간 6회 재발 (2026-07-03, 07-06, 07-08×2, 07-10×2).

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• RDS 슬로우 쿼리 / InnoDB lock 지표 확인 — cupixworks-api production ap-southeast-2 RDS 에서 07:47–07:52 UTC 구간 SHOW ENGINE INNODB STATUS 스냅샷, performance_schema.data_locks / data_lock_waits 조회로 어떤 트랜잭션이 어떤 row 를 오래 잡고 있었는지 특정. 근거: sibling cluster RCA(c25d10f8-…) 와 동일 근본 원인이므로 우선 DB 측 원인(장기 트랜잭션, 대량 UPDATE, 옵티마이저 플랜 변경 등) 을 먼저 확인해야 함.
• status board scope 재분류 검토 (error-sweeper 저장소, svc:*::unknown 자동 분류) — Mysql2::Error::TimeoutError / ActiveRecord::LockWaitTimeout 시그니처를 감지해 dep:rds-mysql-* scope 로 승격시키면 재발 시 대응이 빨라짐.

단기 개선 (1주 이내)#

• ActiveRecord::LockWaitTimeout 별도 rescue (app/factories/base_factory.rb:123-140, MultipleResourcableController#create_resource) — 현재 StandardError 계열로 잡혀 502 로 렌더됨. 별도 rescue 절로 429/503 + Retry-After 응답 + warn 로그 레벨 + Datadog 메트릭 emit 을 방향으로 설정. sibling RCA 와 공통 조치.
• MultipleResourcableController#create_resource 의 중복 검사 원자화 — 현재 find_by_kind 로 pre-check 후 save 하는 구조(multiple_resourcable_controller.rb:52-63) 는 동시성 하에서 TOCTOU 취약. DB 레벨 unique constraint (resources(resourcable_type, resourcable_id, kind) 부분 index) 를 활용하거나 ActiveRecord::RecordNotUnique 를 잡아 idempotent 하게 400/200 을 반환하도록 방향 조정. 이번 사건에서 대상 요청이 락 대기 후 400 을 받은 것도 이 pre-check 가 원인.
• cupix-agent 클라이언트 idempotency — 동일 session/user 가 POST /bims/:id/resources 를 91초 간격으로 두 번 발행한 패턴 확인 필요. agent 측 재시도 정책에 idempotency-key 또는 지수 backoff 및 응답 대기 상한 도입 검토 (별도 저장소, 이 RCA 범위 밖).

장기 개선 (재발 방지)#

• DB 관측성 강화: innodb_row_lock_time_avg / innodb_row_lock_waits / mysql.innodb.row_lock_current_waits 를 Datadog 대시보드 상시 노출.
• svc:cupixworks-api::unknown recent 인시던트 6건 회고: 최근 7일간 재발. 이번 및 sibling RCA 로 최소 두 건은 DB lock contention 확정 — 나머지 4건도 동일 원인인지 배치 재조사 후 공통 대책 수립.
• counter_culture / EntityUpdates::Child 재검토 — Bim/Resource/Facility 체인의 부모 row touch 가 write concurrency 를 떨어뜨리는 주요 경로일 수 있음. 배치화 또는 async 화 검토.

Monitoring#

Datadog 쿼리(각 timeseries widget 에 그대로 사용 가능한 형태):

sum:trace.rack.request.errors{service:cupixworks-api,error.type:ActiveRecord::LockWaitTimeout,env:production}.as_count()

p95:trace.rack.request{service:cupixworks-api,resource_name:api::v1::bimscontroller#create_resource,env:production,region:ap-southeast-2}

p99:trace.rack.request{service:cupixworks-api,env:production,region:ap-southeast-2} by {resource_name}

sum:mysql.innodb.row_lock_waits{env:production,region:ap-southeast-2}.as_rate()

avg:mysql.innodb.row_lock_time_avg{env:production,region:ap-southeast-2}

sum:trace.rack.request{service:cupixworks-api,resource_name:api::v1::bimscontroller#create_resource,http.status_code:400,env:production}.as_count()

알림 추가 제안:

• logs("service:cupixworks-api \"Lock wait timeout exceeded\" env:production") 5분 창 3건 이상 → PagerDuty.
• BimsController#create_resource p95 30s 초과 지속 시 warning.

Risk Assessment#

• Risk level: medium
  • 이번 이벤트는 ~4분 만에 자연 해소, 대상 요청은 400 으로 응답됨(500대 아님). 그러나 같은 시간대 502 3건 + 60s+ 지연 19건 발생, svc:cupixworks-api::unknown scope 로 최근 7일 6회 재발 → 재발 확률 높음.
• 예상 복잡도: standard
  • 즉시 조치(RDS 지표 확인 + status board scope 승격) 는 낮은 복잡도.
  • 단기 조치(LockWaitTimeout 전용 rescue, unique constraint 도입) 는 표준 크기 PR.
  • 장기 조치(counter_culture / EntityUpdates::Child 재설계) 는 별도 investigation 필요 — 이번 RCA 범위 밖.