RCA: Api::V1::AssetsController#create 125s latency

Overview#

What Happened#

2026-07-10 16:49 KST 경 cupixworks-api (ap-southeast-2)의 Api::V1::AssetsController#create 요청이 125.5초 소요된 뒤 200 으로 완료됨. 같은 시간대에 built (team 16) 테넌트의 여러 write 엔드포인트가 Mysql2::Error::TimeoutError: Lock wait timeout exceeded (50 s) 로 502 를 반환했고, 다른 write 요청들도 60 s 이상 지연됨. RDS MySQL 의 광범위한 InnoDB row-lock contention 이벤트로 판단됨.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-10 16:47:25 KST — 초기 정상 상태: 동일 capture(81421) CapturesController#update 요청이 810 ms(db 78 ms)로 완료.
2. 2026-07-10 16:48:47 KST — 첫 이상 조짐: capture 81421 update 가 39.8 s(db 33.4 s)로 지연.
3. 2026-07-10 16:49:21 KST — 대상 클러스터 이벤트 발생 시각 (first_seen). scs-assetfuture 팀에서 POST /api/v1/assets(capture 81477, 3.mp4) 시작 — 이 시점부터 클러스터 카운트가 잡힘.
4. 2026-07-10 16:51:16–16:51:20 KST — built 테넌트의 세 개 요청이 정확히 50 s 만에 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 로 502 반환 (Api::V1::AssetsController#update, Api::V1::PanosController#check_tile_uploading, Api::V1::CapturesController#update).
5. 2026-07-10 16:51:27 KST — 락이 해제되면서 대상 AssetsController#create 요청이 125.5 s 만에 200 으로 완료. 같은 초에 19 건의 60 s 이상 걸린 요청이 일제히 완료됨(파노 stitched/check_tile_uploading, asset update, bim create_resource 등).
6. 2026-07-10 16:51:32 KST — capture 81421 update 가 다시 810 ms 수준으로 회복.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::AssetsController#create",
  "service": "cupixworks-api",
  "occurrences": 1,
  "avg_ms": 125457,
  "max_ms": 125457,
  "sample_trace_id": "3316835142306442741"
}

Impact#

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

Sibling 클러스터(ca6ef0b7-… RoomsController#create 49.7 s, c9b5537f-… BimsController#create_resource 111.7 s, 5a1789e2-…)와 함께 status board 인시던트 2026-07-10-svc-cupixworks-api--unknown-2(resolved, 2026-07-10T07:40:16Z–07:49:35Z)로 묶여 있음. 동일 시간대에 60 s 초과 요청 19 건 확인 — 클러스터 자체 카운트는 낮지만 실 사용자 영향(모바일 업로드 UI 대기, 502 응답)은 훨씬 넓은 범위임.

Root Cause Summary#

RDS MySQL(ap-southeast-2) 에서 다중 write 엔드포인트가 동일 부모 row(특히 built 테넌트의 Capture#81421 및 그 자식 Pano, Asset) 를 대상으로 동시에 UPDATE 를 시도하면서 InnoDB row-lock 대기열이 쌓임. Capture 모델은 counter_culture / counter_cache 를 통해 Facility, Record, Level 및 자식 리소스 삽입/수정마다 부모 row 를 UPDATE 하도록 되어 있어, 하나의 캡처를 동시에 편집하는 여러 요청(모바일 업로드 + agent 의 pano/tile/voxel 업로드)이 서로의 락을 대기하게 됨. innodb_lock_wait_timeout 기본값(50 s)에 도달한 요청은 ActiveRecord::LockWaitTimeout 로 502 를 반환했고, 대기 큐 뒤쪽에서 성공한 요청들(대상 AssetsController#create 포함)은 락 해제 후 남은 처리 시간이 더해져 총 45–125 s 지연되었음.

Technical Analysis#

Code Path#

Entry point: app/controllers/api/v1/assets_controller.rb:27-31

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

  super
end

Assetable lookup + Asset 생성: app/factories/asset_factory.rb:5-34

def create!(params = {})
  # ...
  self.model = ::Asset.new
  _assetable =
    if params[:capture_id].present?
      CaptureRepository.new(
        current_user: current_user,
        review: @review
      ).show(params[:capture_id])
    # ...
    end

  model.assetable = _assetable
  model.facility = _assetable.facility

  super
end

Failure(대기) point: app/factories/base_factory.rb:123-125 — save! 가 트랜잭션을 열고 assets INSERT + captures / facilities / records / levels 등 부모 row 의 UPDATE(counter_cache/counter_culture, EntityUpdates::Child 훅) 를 실행. 이 시점에서 InnoDB row-lock 을 획득해야 하는데, 다른 요청이 이미 같은 부모 row 를 잠그고 있으면 최대 innodb_lock_wait_timeout 초까지 대기.

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 자체는 Mysql2::Error::TimeoutError 를 감싸고 StandardError 계열이므로 이 rescue 체인에서는 Cupix::Errors::System(SYS50000) 로 랩된 뒤 상위에서 502 로 렌더됨(동일 시간대 sibling PUT /api/v1/assets/… 502 응답으로 확인). 단, 대상 요청은 락을 획득하는 데 성공했기 때문에 예외 없이 200 으로 완료됨 — db: 45651.01 ms 는 실질적으로 락 대기 + 실제 쿼리 시간의 합.

Capture 모델의 counter/cache 관계 (락 확산 경로): app/models/capture.rb:76-90

belongs_to :team, optional: true
belongs_to :user, optional: true
belongs_to :workspace, optional: true
belongs_to :facility, counter_cache: true
belongs_to :record, optional: true
belongs_to :level, optional: true
belongs_to :source_capture, class_name: 'Capture', optional: true

has_many :clusters, dependent: :destroy
has_many :videos, dependent: :destroy
has_many :nodes, dependent: :destroy
has_many :pointclouds, dependent: :destroy
has_many :associated_deviations, class_name: 'DeviationCapture', dependent: :destroy
has_many :associated_sitetracks, class_name: 'SitetrackCapture', dependent: :destroy
has_many :assets, as: :assetable, dependent: :destroy

# ...
counter_culture :record,
                column_name: proc { |model| model.untrashed? && !model.skip_counter_culture? ? 'captures_count' : nil },
                column_names: { ::Capture.untrashed => :captures_count },
                execute_after_commit: true

• facility 의 counter_cache: true 는 Capture insert/destroy 시 facilities.captures_count UPDATE 를 유발.
• counter_culture :record, :level 은 같은 캡처가 상태 전이(untrashed) 되거나 자식 리소스가 추가될 때 부모 row UPDATE 를 유발.
• Asset(assetable: Capture) INSERT 는 트랜잭션 내에서 capture 관련 훅을 발생시킬 수 있고, 동시에 진행되는 다른 요청(PUT capture / PUT pano / bim create_resource) 들이 동일 부모 row 에 대해 UPDATE 를 시도하면서 큐가 형성됨.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "AssetsController#create"
service:cupixworks-api status:error
service:cupixworks-api status:warn
service:cupixworks-api "Lock wait timeout"
service:cupixworks-api @duration:>60000
service:cupixworks-api "81421" @duration:>10000

시간 범위: 2026-07-10T07:40:00Z – 2026-07-10T07:55:00Z.

대상 클러스터 요청 로그 (원문 발췌):

{
  "@timestamp": "2026-07-10T07:51:27.211Z",
  "controller": "Api::V1::AssetsController",
  "action": "create",
  "duration": 125455.12,
  "db": 45651.01,
  "http": { "status_code": 200, "method": "POST" },
  "params": { "name": "3.mp4", "capture_id": 81477 },
  "tenant": "cupix",
  "team": { "domain": "scs-assetfuture", "id": 165 },
  "user": { "email": "otavionovais@assetfuture.com", "id": 6753 },
  "user_agent": "Dart/3.12 (dart:io)",
  "host": "ip-10-1-147-96.ap-southeast-2.compute.internal",
  "region": "ap-southeast-2",
  "request_id": "9f9f9151-a080-48f4-ae46-3afadd813f4c"
}

duration 125.5 s 중 db 45.6 s. 나머지 ~80 s 는 Rails 스택 내에서 락 획득 대기 이후 이어진 처리 시간(save 후 renderer, serializer 등) 또는 트랜잭션 밖 대기로 추정 — 로그 단일 필드로는 세분화 불가, uncertain.

같은 시간대 502 LockWaitTimeout 로그:

{
  "@timestamp": "2026-07-10T07:51:20.597Z",
  "controller": "Api::V1::CapturesController",
  "action": "update",
  "duration": 50222.24,
  "db": 50180.98,
  "http": { "status_code": 502, "method": "PUT" },
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  },
  "tenant": "cupix",
  "team": { "domain": "built", "id": 16 },
  "user_agent": "cupix-agent",
  "params": { "id": "81421" },
  "request_id": "e4af2b7a-bf27-40c8-b181-fd5f1e43115e"
}

같은 형태로 502 반환된 요청 3 건(자세한 message 는 동일):

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

capture 81421 의 시간대별 지연 진행 (락 큐 형성 → 해소):

07:47:25.031Z   200   duration=810 ms      db=78 ms       (평시)
07:48:47.052Z   200   duration=39,769 ms   db=33,368 ms   (락 큐 시작)
07:51:20.597Z   502   duration=50,222 ms   db=50,180 ms   (LockWaitTimeout)
07:51:29.212Z   200   duration=112,251 ms  db=26,888 ms   (락 해제 후 완료)
07:51:32.378Z   200   duration=5,927 ms    db=5,657 ms    (회복)

같은 시간대 60 s 초과 요청 19 건 요약 — controller 분포:

Api::V1::AssetsController#create              1× (target cluster)
Api::V1::AssetsController#update              3×+
Api::V1::CapturesController#update            2×+
Api::V1::PanosController#check_tile_uploading 4×+
Api::V1::PanosController#stitched             3×+
Api::V1::PanosController#show                 1
Api::V1::BimsController#create_resource       1  ([400] Duplicate kind: mesh)
Api::V1::FloorplansController#update          3
Api::V1::JobsController#show                  1

• 대상 클러스터와 sibling 클러스터가 모두 write 계열 create/update.
• 대부분이 동일 host ip-10-1-19-125 / ip-10-1-147-96(ap-southeast-2) 위에서 완료 — DB(RDS) 문제이지 특정 앱 인스턴스 이슈가 아님.
• 완료 시각이 07:51:27–07:51:29 UTC 로 몰려 있음 → 락 해제 후 큐가 한꺼번에 flush.

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-… (this), c9b5537f-…

동일 원인의 recent 인시던트 6 건(2026-07-03 ~ 2026-07-10) 이 svc:cupixworks-api::unknown scope 로 존재 → 재발 패턴.

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 구간에 어떤 트랜잭션이 어떤 row 를 오래 잡고 있었는지 확인.
  • 근거: 대상 요청 및 502 요청 모두 db 시간이 지배적이며 여러 controller 에 걸친 광범위 lock wait → 단일 코드경로 수정 이전에 DB 측 원인(예: 장기 트랜잭션, 대량 UPDATE, 옵티마이저 플랜 변경) 을 먼저 특정해야 함.
• status board scope 재분류 검토 (error-sweeper 저장소, svc:*::unknown 자동 분류 로직) — 이번 사건은 실질적으로 dep:rds-mysql-ap-southeast-2 인시던트에 가까우므로, Mysql2::Error::TimeoutError / ActiveRecord::LockWaitTimeout 시그니처를 감지해 dep: scope 로 승격시키는 것이 재발 시 대응을 빠르게 만듦.

단기 개선 (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.
  • 방향만 지정, 구현은 별도 PR.
• 동일 capture 에 대한 동시성 상한 — 모바일/agent 클라이언트에서 같은 capture_id 로 여러 asset 을 병렬 POST 하는 패턴이 관측됨(session_id 75ce141b… 가 1.mp4/2.mp4/3.mp4 를 연속 upload). 서버측 rate-limit 또는 클라이언트 측 순차 업로드 전략을 검토.
• counter_culture / counter_cache 재검토 — 특히 Capture 의 execute_after_commit: true counter_culture 관계가 트랜잭션 커밋 전에 부모 row lock 을 어떤 순서로 잡는지 확인. 필요 시 updated_at 갱신을 배치화하거나 counter_culture 를 지연 배치로 전환.

장기 개선 (재발 방지)#

• DB 관측성 강화: RDS enhanced monitoring / pg_stat_statements 상응(MySQL 은 performance_schema events_statements_history_long) 을 활성화하고, innodb_row_lock_time_avg / innodb_row_lock_waits 를 Datadog 대시보드에 상시 노출.
• svc:cupixworks-api::unknown recent 인시던트 6 건 회고: 2026-07-03, 07-06, 07-08(×2), 07-10(×2) 로 최근 7 일간 재발 중. root_cause_types 가 unknown 이지만 이번 조사로 최소 이번 사건은 DB lock contention 임이 확인됨 — 이전 6 건도 동일 원인인지 확인 후 공통 대책 수립.
• write-heavy 엔드포인트의 트랜잭션 범위 축소 — 특히 PanosController#stitched, check_tile_uploading 등 모바일/agent 가 대량 병렬 호출하는 엔드포인트의 SQL 을 optimistic locking 또는 짧은 UPDATE 로 분리.

Monitoring#

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

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

Alternate log-based query:

logs("service:cupixworks-api \"Lock wait timeout exceeded\"").index("*").rollup("count").by("http.url_details.path")

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

p95:trace.mysql.query{service:cupixworks-api,env:production,region:ap-southeast-2}

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}

알림 추가 제안:

• logs("service:cupixworks-api \"Lock wait timeout exceeded\"") 5 분 창 3 건 이상 → PagerDuty (현재 status board 는 클러스터 2 건 이상일 때만 인시던트를 오픈 — 낮은 threshold 의 별도 monitor 필요).
• p95:trace.rack.request{service:cupixworks-api,resource_name:Api::V1::AssetsController#create} 30 s 이상 지속 시 warning.

Risk Assessment#

• Risk level: medium
  • 이번 이벤트 자체는 ~4 분 만에 자연 해소되었고 대상 요청은 200 으로 완료됨. 그러나 같은 시간대 502 응답이 3 건 발생했고 svc:cupixworks-api::unknown scope 로 최근 7 일간 6 회 재발 중이라 재발 확률이 높음.
• 예상 복잡도: standard
  • 즉시 조치(RDS 지표 확인 + status board scope 승격) 는 낮음.
  • 단기 조치(LockWaitTimeout 전용 rescue, 클라이언트 병렬 상한) 는 표준 크기의 PR.
  • 장기 조치(counter_culture 재설계) 는 별도 investigation 필요 — 이번 RCA 범위 밖.