RCA: Api::V1::LevelsController#create (avg 141670ms, max 323409ms)

Overview#

What Happened#

2026-08-03 15:01–15:02 KST 사이 cupixworks-api (ap-southeast-2, env:production, tenant cupix) 에서 POST /api/v1/levels 요청 3건이 평균 141초, 최대 323초까지 지연되었다. 요청은 Mysql2::Error::TimeoutError: Lock wait timeout exceeded 로 500 응답을 냈다. 같은 시간대(14:16–15:16 KST)에 panos/jobs/captures/editings/assets 등 다른 엔드포인트에서도 동일한 Lock wait timeout 이 15건 이상 발생했다. 즉 이 latency 클러스터는 서비스 전반의 row-lock 경합 이벤트의 일부다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-08-03 14:16 KST — PUT /api/v1/panos/15354652/meta/ver 502 (ActiveRecord::LockWaitTimeout). Lock 경합 첫 감지.
2. 2026-08-03 14:22 KST — POST /api/v1/captures/85824/process_output_upload_url 502.
3. 2026-08-03 14:39 KST — PUT /api/v1/assets/kh6cuxohjn4p 502.
4. 2026-08-03 14:51 KST — GET /api/v1/editings 502.
5. 2026-08-03 14:58:50 KST (05:58:50Z) — 클러스터 first_seen 근처, 첫 slow Level create 시작.
6. 2026-08-03 15:01:39 KST (06:01:39Z) — POST /api/v1/levels 500 (500ms request duration 이지만 db=50917ms — 첫 Lock wait timeout 500 응답). team=endeavourgroup, facility_key=8je0s5.
7. 2026-08-03 15:02:31 KST (06:02:31Z) — 동일 팀, 두 번째 POST /api/v1/levels 500 (duration=50938ms, db=50917ms).
8. 2026-08-03 15:04–15:16 KST — Jobs / Panos / Captures endpoint 계속 502.
9. 2026-08-03 15:16:19 KST — 마지막 Lock wait timeout (PUT /api/v1/panos/15364151) 이후 로그에서 소거.

Error Log#

Datadog Logs

{
  "resource_name": "Api::V1::LevelsController#create",
  "service": "cupixworks-api",
  "occurrences": 3,
  "avg_ms": 141670,
  "max_ms": 323409,
  "sample_trace_id": "843918613749923455"
}

Impact#

• Service: cupixworks-api
• 발생 횟수: 3
• 최초 발생: 2026-08-03 14:59 KST
• 최근 발생: 2026-08-03 15:01 KST
• Region: ap-southeast-2, tenant: cupix, team: endeavourgroup (id 180)
• 사용자 영향: CupixConnect 데스크톱에서 Level 생성이 최대 5분 이상 대기 후 500 실패. 동시간대 같은 origin (Sydney 리전 MySQL) 을 공유하는 다른 도메인 (job, capture, pano, asset) 도 502/400 로 함께 실패.

Root Cause Summary#

Level.save! 는 belongs_to :facility 와 counter_culture 를 통해 부모 facility.levels_count (및 조건부 building.levels_count) 를 UPDATE 하는데, 이는 부모 row 에 InnoDB row lock 을 잡는다. 2026-08-03 14:16–15:16 KST 사이 ap-southeast-2 프로덕션에서 동일 부모 row 를 참조하는 다른 트랜잭션 (cupix-capture-postprocessor-agent 가 발행하는 PUT /api/v1/jobs/* 등, 로그에서 duration≈50s, db≈50s 로 확인됨) 이 오랫동안 lock 을 유지하면서 lock waiter chain 이 생성되었다. Level create 요청은 default innodb_lock_wait_timeout (50 s) 을 초과하여 Mysql2::Error::TimeoutError 로 실패했고, BaseFactory#create! 의 fall-through rescue StandardError 가 이를 Cupix::Errors::System(SYS50000) 으로 감싸 500 을 반환했다. 클러스터의 avg 141 s / max 323 s 는 사용자/클라이언트 재시도가 반복적으로 lock wait 사이클을 밟은 결과다 (50 s × 3 ≈ 150 s, 50 s × 6 ≈ 300 s).

Technical Analysis#

Code Path#

• Entry point: app/controllers/api/v1/levels_controller.rb:24-28 — LevelsController#create
• Factory: app/factories/level_factory.rb:5-23 — LevelFactory#create! (부모 facility 로드 후 super)
• Save + rescue: app/factories/base_factory.rb:123-140 — BaseFactory#create! 의 self.model.save! + rescue StandardError
• Locking source: app/models/level.rb:48-54 — counter_culture :facility / counter_culture :building
• Failure point: app/factories/base_factory.rb:124 에서 self.model.save! 가 Mysql2::Error::TimeoutError raise → line 136–139 의 fall-through rescue 가 Cupix::Errors::System(SYS50000) 로 재감쌈.

Level 모델의 counter_culture 선언 — Level insert 시 부모 row 를 UPDATE 하여 lock 유발:

before_create :set_default_name

validate :validate_floorplan_when_floorplan_changed, on: [:update]

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

counter_culture :building,
                column_name: proc { |model| model.building_id.present? && model.untrashed? ? 'levels_count' : nil },
                column_names: { ::Level.untrashed.where.not(building_id: nil) => :levels_count }

LevelFactory 는 facility_key 로 부모를 로드하고 super 호출:

def create!(params = {})
  self.model = ::Level.new

  if params[:facility_key].present?
    self.parent = FacilityRepository.new(current_user: self.current_user).show(params[:facility_key])
  elsif params[:facility].present?
    self.parent = FacilityRepository.new(current_user: self.current_user).show(params[:facility].key)
  else
    raise Cupix::Errors::Parameter.new(code: 'ARG10000', reason: 'facility_key is required')
  end

  self.model.facility = self.parent
  self.model.ground_level = ActiveRecord::Type::Boolean.new.cast(params[:ground_level]) == true
  self.model.default_level = ActiveRecord::Type::Boolean.new.cast(params[:default_level]) == true

  super

  self.model
end

BaseFactory#create! 의 save + rescue chain — Mysql2::Error::TimeoutError 는 StandardError 로 잡혀 SYS50000 으로 감싸짐:

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

기대 동작 vs 실제 동작

• 기대: Level.save! insert + counter_culture UPDATE 가 몇 ms 안에 완료.
• 실제: 부모 facility / building row 를 잡고 있는 다른 트랜잭션이 lock 을 놓지 않아 50 s 이상 대기 → ActiveRecord::LockWaitTimeout (Mysql2::Error::TimeoutError) raise → 500. 사용자 클라이언트가 재시도하면서 총 request 시간이 141–323 s 로 관측됨.

Log Evidence#

Datadog 쿼리:

service:cupixworks-api "Api::V1::LevelsController#create" @timestamp:[2026-08-03T05:00:00Z TO 2026-08-03T07:00:00Z]

핵심 로그 (LevelsController 500, KST 시각으로 병기):

{
  "timestamp": "2026-08-03T06:01:39Z (15:01:39 KST)",
  "message": "[500] POST /api/v1/levels (Api::V1::LevelsController#create)",
  "duration": 50661.02,
  "db": 50625.xx,
  "params": { "facility_key": "8je0s5", "name": "Coldroom" },
  "team": { "domain": "endeavourgroup", "id": 180 },
  "user_agent": "Mozilla/5.0 ... CupixConnect/2026.2.1 Electron/41.2.0 ...",
  "error": {
    "reason": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "code": "SYS50000",
    "class": "Cupix::Errors::System"
  },
  "tags": ["env:production", "region:ap-southeast-2", "version:production-ap-southeast-2-20260731t0617z0-5d9c7658-cupixworks"]
}

{
  "timestamp": "2026-08-03T06:02:31Z (15:02:31 KST)",
  "message": "[500] POST /api/v1/levels (Api::V1::LevelsController#create)",
  "duration": 50938.05,
  "db": 50917.12,
  "params": { "facility_key": "8je0s5", "name": "Coldroom" },
  "team": { "domain": "endeavourgroup", "id": 180 },
  "error": {
    "reason": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "code": "SYS50000",
    "class": "Cupix::Errors::System"
  }
}

같은 시간대에 다른 endpoint 도 동일 원인:

service:cupixworks-api "Lock wait timeout" @timestamp:[2026-08-03T05:30:00Z TO 2026-08-03T06:30:00Z]
→ 18건 (LevelsController 2건 + JobsController#update 6건 + PanosController#update 4건 + CapturesController#update 3건 + EditingsController#index 1건 + AssetsController#update 1건 + JobsController#update 1건)

한 예시 (Jobs endpoint):

{
  "timestamp": "2026-08-03T06:04:19Z (15:04:19 KST)",
  "message": "[502] PUT /api/v1/jobs/241636 (Api::V1::JobsController#update)",
  "duration": 50362.44,
  "db": 50321.46,
  "params": { "error_code": "AGT2400", "state": "stopped", "id": "241636" },
  "team": { "domain": "scs-assetfuture", "id": 165 },
  "user_agent": "cupix-capture-postprocessor-agent",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

db≈50000ms (거의 정확히 default innodb_lock_wait_timeout = 50 s) 이 여러 endpoint 에서 반복되는 것은 waiter 들이 timeout 상한까지 대기하다 실패했다는 신호.

주의: 클러스터 파일의 avg 141 s / max 323 s 는 APM trace duration (재시도 포함 root span) 인 반면, 개별 request log 의 duration≈50 s 는 단일 request. 클라이언트 재시도 로직이 trace 를 확장한 것으로 보인다 — 사용자별로 3회 정도 재시도.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

1. DBA 세션 검사로 lock holder 확정 (코드 변경 없음, 운영 조치)

   • ap-southeast-2 production RDS 에서 SELECT * FROM performance_schema.data_lock_waits; / SELECT * FROM information_schema.innodb_trx WHERE trx_state='LOCK WAIT'; 히스토리 확인.
   • cupix-capture-postprocessor-agent 의 PUT /api/v1/jobs/* 트랜잭션 스코프 리뷰 — Job 업데이트가 부모 facility/building 을 함께 락한다면 별도 fix cluster 로 이관.

2. BaseFactory#create! 에서 ActiveRecord::LockWaitTimeout 을 별도 rescue 로 분리

   • 대상: app/factories/base_factory.rb:126-139
   • 근거: 현재는 rescue StandardError 에 잡혀 SYS50000 으로 500 을 반환. Lock wait timeout 은 transient / retryable 이므로 별도 error class (예: Cupix::Errors::ServiceUnavailable 계열 또는 신규 code) 로 라벨링해 클라이언트/모니터링이 구분 가능하도록 함. 재시도 안전성 확인 후 상위 계층에서 짧은 retry 도 고려. (구현 없이 방향만 — 팀 로거/에러 convention 검토 필요)

3. counter_culture hot row 완화 검토

   • app/models/level.rb:48-54 의 두 counter_culture 는 매 Level 생성마다 부모 facility 와 building 을 즉시 UPDATE. 특정 facility 에 많은 Level 이 짧은 시간에 생성되는 워크플로 (bulk import, 데스크톱 클라이언트) 에서 hot row 를 만든다.
   • 대안: counter_culture ... execute_after_commit: true (async column update) 또는 after_commit 기반 background job 으로 카운터 UPDATE 를 분리해 짧은 lock hold 로 축소. (구현 방향만 — counter_culture gem 옵션 및 정합성 트레이드오프는 리뷰 필요)

단기 개선 (1주 이내)#

1. cupix-capture-postprocessor-agent 의 Jobs update 트랜잭션 감사
   • 로그로 확인된 lock waiter chain 의 상류가 이 agent 로 강하게 시사됨. Api::V1::JobsController#update 가 사용하는 factory/repository 를 리뷰해 트랜잭션이 부모 row 를 오래 잡지 않는지 (외부 API 호출·S3·SES 를 트랜잭션 안에서 부르지 않는지) 확인.
2. Long-running transaction 알림 추가
   • RDS long_query_log / pt-stalk / CloudWatch RDS metric DatabaseConnections + Deadlocks + InnoDBLockWaitTime 임계값 알림. 특히 sum:mysql.innodb.row_lock_time_avg 상승 알림.
3. Client-side 재시도 정책 재검토
   • CupixConnect 데스크톱이 3회 이상 재시도해 trace duration 이 300 s+ 가 되는 것으로 보임. 재시도 backoff / max attempt 하향 조정 검토 (프런트엔드/데스크톱 담당자와 조율 필요).

장기 개선 (재발 방지)#

• Level, Capture, Pano, Asset, Job 등 다수 model 이 counter_culture 로 동일 부모 (facility/building) row 를 UPDATE 한다면 부모가 시스템의 write hot spot. 카운터 aggregation 을 materialized view / OLAP 사이드로 옮기거나 counter row 를 shard 하는 (예: counter_shards) 아키텍처 개선 검토.
• Row-lock hot spot 조기 감지를 위한 대시보드 (per-parent lock wait duration histogram) 추가.

Monitoring#

Datadog 대시보드 위젯용 timeseries 쿼리:

count:cupixworks-api{env:production,region:ap-southeast-2,error.class:ActiveRecord::LockWaitTimeout}.as_count()

count:cupixworks-api{env:production,region:ap-southeast-2}.rollup(count, 60).by{resource_name}

avg:trace.rack.request.duration{service:cupixworks-api,resource_name:api::v1::levelscontroller#create,env:production}

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

• 알림 대상: error.class:ActiveRecord::LockWaitTimeout 이 5분 동안 5회 이상 발생 시 page (region 별).
• 추가 지표: mysql.innodb.row_lock_time_avg, mysql.innodb.row_lock_waits (per-region, ap-southeast-2).

Risk Assessment#

• Risk level: medium — 사용자 영향은 특정 팀 (endeavourgroup 등) 의 짧은 시간대 3건이지만, 동일 원인이 15+ 다른 요청 실패로 확산됨. 재발 가능성은 counter_culture 아키텍처와 postprocessor-agent 워크로드에 의존.
• 예상 복잡도: standard — rescue 분기 추가는 trivial, counter_culture async 전환 및 Jobs update 트랜잭션 감사는 standard.