RCA: ActiveRecord::LockWaitTimeout: Mysql2::Error::TimeoutError: Lock wait timeout exceeded

Overview#

What Happened#

cupixworks-api (tesla) 에서 InnoDB row-lock 대기 시간 초과(Mysql2::Error::TimeoutError: Lock wait timeout exceeded)가 여러 write 엔드포인트에 걸쳐 산발적으로 발생했다. 이 Error Tracking issue 는 특정 코드 경로 하나가 아니라, 동시 쓰기 부하 상황에서 같은 행/인접 행을 두고 트랜잭션이 서로의 잠금을 기다리다 InnoDB innodb_lock_wait_timeout(기본 50s) 을 넘긴 케이스들을 하나로 묶은 것이다. tesla 는 이미 이 예외를 controller 레벨에서 rescue_from 하여 재시도 가능한 502 BadGateway 로 변환하고 있어, 미처리 크래시나 nil 참조 같은 코드 결함이 아니다.

Quick Facts#

Affected Teams#

Datadog 최근 14일 로그(100건 표본) 상 여러 엔드포인트에 분산되어 특정 도메인에 집중되지 않는다.

Timeline#

1. 2024-08-16 12:53 KST — Error Tracking issue 최초 감지 (first_seen, 대표 샘플은 이 시점 기준으로 stale)
2. 2026-08-03 17:43~17:46 KST — ElementTracesController#bulk 에서 연속 502 burst
3. 2026-08-04 13:06~13:08 KST — PanosController#update / check_tile_uploading / check_mask_uploading 동일 pano ID 대상 burst
4. 2026-08-04 13:40~13:46 KST — ElementTracesController#bulk 재발 (last_seen)

Error Log#

Datadog Logs

Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixworks-api
• 발생 횟수: 384 (Error Tracking 누적, 2024-08 이후)
• 최초 발생: 2024-08-16 12:53 KST
• 최근 발생: 2026-08-04 13:46 KST

Root Cause Summary#

동시 쓰기 트랜잭션 간의 InnoDB row-lock 경합이 근본 원인이다. 여러 요청이 같은(또는 인접한) 행에 대해 배타 잠금(FOR UPDATE / UPDATE)을 잡으려 할 때, 선행 트랜잭션이 잠금을 오래 붙들면 후행 트랜잭션은 innodb_lock_wait_timeout 을 초과하여 Mysql2::Error::TimeoutError 를 받는다. 특히 ElementTracesController#bulk 는 bulkable_repository.rb 에서 최대 1000개 항목을 하나의 요청 흐름 안에서 순차 update 하며 잠금을 누적 보유하고, 동일 parent 를 편집하는 동시 요청이 겹칠 때 경합이 심화된다. 이는 특정 nil/schema/logic 결함이 아니라 부하·동시성 특성이며, tesla 는 해당 예외를 이미 rescue_from ActiveRecord::LockWaitTimeout → 재시도 가능한 502 BadGateway 로 처리하고 있다(server_error_controller.rb:18-20). Error Tracking 은 서로 다른 엔드포인트의 timeout 을 대표 메시지 하나로 묶었고, 대표 샘플의 first_seen(2024-08) 은 stale 하지만 last_seen(2026-08-04) 최근 로그도 동일한 메시지/클래스 임을 확인했다.

Technical Analysis#

Code Path#

• Controller 레벨에서 ActiveRecord::LockWaitTimeout 는 502 로 rescue 됨 — 미처리 예외가 아니다:

    rescue_from ActiveRecord::LockWaitTimeout,
                Errno::ENOMEM,
                RuntimeError, with: :badgateway_on_system_502_error
    # ...
    rescue_from ActiveRecord::WrappedDatabaseException,
                # ...
                # ActiveRecord::LockWaitTimeout,   # ← 503 그룹에서 명시적으로 제외됨
                ActiveRecord::StatementTimeout,

주석 처리된 line 32 는 LockWaitTimeout 을 503 그룹에서 빼서 502(BadGateway, 재시도 가능) 그룹으로 의도적으로 옮긴 흔적이다. 즉 팀은 lock wait timeout 을 "일시적·재시도 가능" 조건으로 이미 취급하고 있다.

• 경합이 집중되는 대표 경로 — ElementTracesController#bulk → BulkableRepository#bulk!:

      case params[:bulk_action]
      when 'update'
        _models.each_with_index do |model, index|
          _repository = self.class.new(review: _review, current_user: current_user, model: model, parent: _parent)
          _item = params[:items].find { |x| x[:id] == model.id }
          next if _item.nil?
          # ...
          _repository.update(_item.except(:id))
        rescue StandardError => e
          _invalid_items << { index: index }.merge(Cupix::Util::ErrorParser.parse_error(e))
          next
        end

한 요청이 최대 1000개(bulk_default_validation! line 97) 항목을 순차 update 하며 잠금을 누적 보유 → 동일 parent 를 편집하는 동시 bulk 요청이 서로 대기하며 timeout.

• 팀이 이미 동일 원인을 인지하고 배치 처리로 완화한 흔적:

      # Update ElementTrace and Element editing_id (batched to avoid LockWaitTimeout)
      et_ids = ::ElementTrace.where(task_id: task_ids, editing_id: editing.id).pluck(:id)
      et_affected_total = 0
      if et_ids.any?
        et_ids.each_slice(REASSIGN_BATCH_SIZE) do |batch|
          et_affected_total += ::ElementTrace.where(id: batch).update_all(editing_id: new_editing.id)
        end
      end

• worker 및 모델 concern 에서도 이미 rescue 됨: app/workers/task_sync_worker.rb:53 (rescue ActiveRecord::LockWaitTimeout => e), app/models/concerns/finalization/editing_entity.rb:20 (rescue ActiveRecord::LockWaitTimeout, ActiveRecord::Deadlocked => e).

기대 동작: 동시 write 는 짧은 잠금 후 커밋되어야 함. 실제 동작: 대량/장기 트랜잭션이 잠금을 오래 보유 → 후행 트랜잭션이 50s 초과 → timeout → 502 반환(클라이언트 재시도 가능).

참고: develop HEAD(790e093bb, 2026-06-02)에는 check_tile_uploading / check_mask_uploading 액션이 존재하지 않는다(routes 리네임 추정). 그러나 근본 원인은 엔드포인트별 로직이 아니라 공통된 InnoDB 잠금 경합이므로 분석 결론에 영향 없음 — uncertain 부분은 엔드포인트 매핑에 한정.

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-api "Lock wait timeout exceeded"

최근(now-14d) 표본 100건의 엔드포인트 분포 — 단일 경로가 아니라 다수 write 엔드포인트에 분산:

     17 (Api::V1::ElementTracesController#bulk)
      8 (Api::V1::PanosController#update)
      7 (Api::V1::JobsController#update)
      3 (Api::V1::PanosController#check_tile_uploading)
      3 (Api::V1::PanosController#check_mask_uploading)
      3 (Api::V1::CapturesController#update)
      2 (Api::V1::PanosController#update_meta_by_key)
      2 (Api::V1::LevelsController#create)
      1 (Api::V1::EditingsController#index)
      1 (Api::V1::CapturesController#process_output_upload_url)
      1 (Api::V1::AssetsController#update)

last_seen 근처 실제 최근 로그 — 대표 메시지와 동일(stale 아님), 502 로 정상 처리됨:

{
  "timestamp": "2026-08-04 13:46:54",
  "status": "info",
  "message": "[502] PUT /api/v1/element_traces (Api::V1::ElementTracesController#bulk)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

동일 pano ID 를 대상으로 한 concurrent burst(13:06~13:08) — 같은 행에 대한 경합 정황:

{
  "timestamp": "2026-08-04 13:07:46",
  "status": "info",
  "message": "[502] PUT /api/v1/panos/10942650 (Api::V1::PanosController#update)",
  "error": {
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "ActiveRecord::LockWaitTimeout"
  }
}

일부는 파라미터 검증 경로에서 400 으로 wrap 되어 나타남(클라이언트 입력 경합 케이스):

{
  "timestamp": "2026-08-04 13:06:04",
  "status": "info",
  "message": "[400] PUT /api/v1/panos/10942650 (Api::V1::PanosController#update)",
  "error": {
    "reason": "Invalid argument",
    "code": "ARG10001",
    "message": "Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
    "class": "Cupix::Errors::Parameter"
  }
}

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 코드 변경 불필요. ActiveRecord::LockWaitTimeout 는 이미 502(BadGateway, 재시도 가능) 로 rescue 되고 있으며(server_error_controller.rb:18-20), 이는 일시적 DB 경합에 대한 적절한 처리다. 새 PR 대상이 아니다.
• (운영) 필요 시 Error Tracking 에서 본 issue 를 muted/expected 로 분류하여 alerting noise 감소.

단기 개선 (1주 이내)#

• ElementTracesController#bulk → BulkableRepository#bulk! 의 순차 update 를 배치/청크 트랜잭션으로 분할하여 단일 요청의 잠금 보유 시간을 단축하는 방안 검토(bulkable_repository.rb:28-46). editing_split_service.rb:769 의 each_slice(REASSIGN_BATCH_SIZE) 패턴을 참고.
• 대량 bulk 요청 상한(현재 1000, bulkable_repository.rb:97) 이 잠금 경합에 미치는 영향을 메트릭으로 계측 후 필요 시 하향 조정.

장기 개선 (재발 방지)#

• 클라이언트단에 502(BadGateway) 응답에 대한 idempotent 재시도(backoff) 정책이 있는지 확인 — 없으면 프런트엔드/SDK 담당자와 협의(자동 code-fix 대상 아님).
• 핫 레코드(동일 pano/element_trace 동시 편집)에 대한 낙관적 잠금(optimistic locking) 또는 애플리케이션 레벨 직렬화 도입 검토.
• DB 레벨에서 장기 트랜잭션 모니터링(INFORMATION_SCHEMA.INNODB_TRX, lock wait 그래프) 상시화.

Monitoring#

lock wait timeout 발생 추이(엔드포인트 무관, 502 처리 포함):

service:cupixworks-api "Lock wait timeout exceeded"

bulk 경로 집중 모니터링:

service:cupixworks-api "Lock wait timeout exceeded" "ElementTracesController#bulk"

Risk Assessment#

• Risk level: low
• 예상 복잡도: trivial (즉시 조치는 no-op; 단기 개선은 standard)

Noise Verdict#

noise — LockWaitTimeout 은 동시 쓰기 부하에서 발생하는 일시적 InnoDB 잠금 경합이며, tesla 가 이미 재시도 가능한 502 로 정상 처리하고 있어 코드 결함이 아니다.