RCA: flush_geo_coordinate - Mysql2::Error::TimeoutError: Lock wait timeout exceeded

Overview#

What Happened#

2026-04-23 08:1508:34 UTC (KST 17:1517:34) 사이에 cupixworks-worker 서비스의 flush_geo_coordinate 메서드에서 MySQL Lock wait timeout exceeded 에러가 2건 발생했다. 동일 시간대에 다수의 flush_geo_coordinate 작업이 동시 실행되면서 records 테이블의 행 잠금 경합이 발생한 것이 원인이다.

Quick Facts#

Timeline#

1. 2026-04-23 08:10~08:20 UTC — 10분간 20건 이상의 flush_geo_coordinate - begin 로그 관측. 다수 worker가 동시에 flush 작업 수행 중.
2. 2026-04-23 08:15:15 UTC — 첫 번째 Lock wait timeout exceeded 에러 발생.
3. 2026-04-23 08:17:57 UTC — 동일 시간대에 PullTaskWorker에서도 Lock wait timeout exceeded 에러 발생 (records 테이블 경합 확산).
4. 2026-04-23 08:34:17 UTC — 두 번째 Lock wait timeout exceeded 에러 발생.
5. 2026-04-23 08:34 UTC 이후 — 경합 자연 해소. 이후 flush 작업은 정상 완료.

Error Log#

Datadog Logs

flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

Impact#

• Service: cupixworks-worker
• 발생 횟수: 2
• 최초 발생: 2026-04-23T08:15:15.500Z
• 최근 발생: 2026-04-23T08:34:17.839Z

해당 에러가 발생한 Record의 geo_coordinate 파일이 S3에 즉시 업로드되지 못했다. 다만, 에러 발생 후 Redis 캐시 락이 해제되고(unlock_flushing_geo_coordinate), 후속 cron 작업이나 worker 재시도가 결국 flush를 완료하므로 데이터 영구 손실은 없다. 동일 시간대에 PullTaskWorker도 lock timeout을 겪어 다른 worker 작업에도 일시적 지연이 발생했다.

Root Cause Summary#

flush_geo_coordinate 메서드는 S3 streaming upload 후 update(geo_coordinate_url_updated_at:) (line 83)로 records 테이블의 행을 업데이트한다. 이 과정에서 MySQL 행 잠금(row lock)을 획득하는데, 동시에 다수의 Sidekiq worker와 cron 작업이 서로 다른 Record에 대해 flush를 실행하면서 S3 upload가 장시간 진행되는 동안 다른 트랜잭션이 같은 행의 잠금을 대기하게 된다. MySQL의 innodb_lock_wait_timeout (기본 50초)을 초과하면 Lock wait timeout exceeded 에러가 발생한다.

특히 Redis 기반의 lock_flushing_geo_coordinate 메커니즘은 동일 Record의 동시 flush만 방지하지만, cron 작업(flush_stale_records, flush_refreshing_records, finalize_delayed_geo_coordinate)에서 직접 flush_geo_coordinate를 호출할 때는 이 lock을 확인하지 않는다. 또한 in_batches (line 54)로 panos를 순회하면서 각 batch마다 DB 쿼리를 실행하므로, Record에 pano가 많을 경우 전체 트랜잭션 시간이 길어져 lock 경합 가능성이 높아진다.

Technical Analysis#

Code Path#

• Entry point: FlushRecordGeoCoordinateWorker#perform — app/workers/flush_record_geo_coordinate_worker.rb:7
• Record를 찾고 flush_geo_coordinate를 호출한다.

def perform(record_id = nil, accept_delay = false)
  return if record_id.nil?

  record = Record.find_by_id(record_id)
  Cupix::Logger.error("Record not found: #{record_id}") and return if record.nil?

  # ... heavy team domain skip logic ...

  _flushing_geo_coordinate_locked = record.flushing_geo_coordinate_locked?

  begin
    if _flushing_geo_coordinate_locked
      Cupix::Logger.info("Flushing geo_coordinate delayed: #{record_id}", ...)
      record.flush_geo_coordinate(accept_delay: true)
    else
      record.flush_geo_coordinate(accept_delay: accept_delay)
    end
  rescue StandardError => e
    Cupix::Logger.error('Unlocked flushing geo_coordinate with error', ...)
    record.unlock_flushing_geo_coordinate
  end
end

• flush_geo_coordinate 메서드: app/models/concerns/record_geo_coordinate.rb:37
• Redis 캐시 락을 설정한 뒤, S3에 pano 데이터를 streaming upload하고, 마지막에 update 호출.

def flush_geo_coordinate(accept_delay: false)
  lock_flushing_geo_coordinate                    # Redis lock 설정

  _delayed_flush_geo_coordinate and return if accept_delay

  # S3 streaming upload (panos를 in_batches로 순회)
  geo_coordinate_s3_object.upload_stream(...) do |write_stream|
    panos.where(capture: captures.untrashed.published)
         .published.untrashed
         .eager_load(:capture, { capture: :capture_type })
         .in_batches(of: 1000).each_with_index do |pano_batch, index|
      # ... JSON 직렬화 및 stream 쓰기 ...
    end
  end

  update(geo_coordinate_url_updated_at: DateTime.now)  # ← Failure point (line 83)

  fresh_fresh_state!

rescue StandardError => e
  unlock_flushing_geo_coordinate
  Cupix::Logger.error("flush_geo_coordinate - error - message: #{e.message}", ...)
  false
else
  unlock_flushing_geo_coordinate
end

• Failure point: app/models/concerns/record_geo_coordinate.rb:83 — update(geo_coordinate_url_updated_at: DateTime.now) 호출 시 MySQL이 records 행에 대한 exclusive lock을 획득하려 하지만, 다른 트랜잭션이 이미 해당 행을 잠그고 있어 50초 대기 후 timeout.

• Cron 경로 (lock 미확인): lib/cupix/cron/record.rb:8-13

def flush_stale_records
  ::Record.stale_over_hour.each(&:flush_geo_coordinate)  # lock 확인 없이 직접 호출
end

def flush_refreshing_records
  ::Record.refreshing_over_hour.each(&:flush_geo_coordinate)  # lock 확인 없이 직접 호출
end

• finalize_delayed_geo_coordinate 역시 record.flush_geo_coordinate를 직접 호출 (lib/cupix/cron/record.rb:33).

Log Evidence#

사용한 Datadog 쿼리:

service:cupixworks-worker status:error "flush_geo_coordinate" "Lock wait timeout"
from:2026-04-23T07:00:00Z to:2026-04-23T09:30:00Z

Lock timeout 에러 2건:

{
  "timestamp": "2026-04-23 17:15:15 KST",
  "status": "error",
  "message": "flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
  "class": "Record",
  "function": "flush_geo_coordinate"
}

{
  "timestamp": "2026-04-23 17:34:17 KST",
  "status": "error",
  "message": "flush_geo_coordinate - error - message: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
  "class": "Record",
  "function": "flush_geo_coordinate"
}

동시 실행 증거 — 08:10~08:20 UTC (10분) 동안 20건 이상의 flush_geo_coordinate - begin 로그:

service:cupixworks-worker "flush_geo_coordinate" "begin"
from:2026-04-23T08:10:00Z to:2026-04-23T08:20:00Z
→ 20건 (limit 도달, 실제 더 많을 수 있음)

동일 시간대 PullTaskWorker 경합:

{
  "timestamp": "2026-04-23 17:17:57 KST",
  "status": "error",
  "message": "PullTaskWorker::perform | error on 771599 - Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction",
  "class": "PullTaskWorker",
  "function": "perform"
}

동일 Record에 대한 반복 지연 flush (record ID 16094에 대해 18:06~18:22 사이 8건 이상):

service:cupixworks-worker "Flushing geo_coordinate delayed"
→ record 16094: 8건, record 126101: 5건 (같은 record에 대한 반복 flush 시도)

S3/네트워크 타임아웃도 동시 발생 (같은 시간대):

{
  "timestamp": "2026-04-23 17:16:19 KST",
  "status": "error",
  "message": "flush_geo_coordinate - error - message: Failed to open TCP connection to s3.me-south-1.amazonaws.com:443 (execution expired)"
}

{
  "timestamp": "2026-04-23 17:10:32 KST",
  "status": "error",
  "message": "flush_geo_coordinate - error - message: Failed to open TCP connection to 207.127.99.67:80 (execution expired)"
}

S3 upload가 네트워크 문제로 지연되면 트랜잭션이 더 오래 열리게 되어 lock 경합이 악화된다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• app/models/concerns/record_geo_coordinate.rb:83 — update 호출에 retry 로직 추가. MySQL lock timeout은 일시적이므로 1~2회 재시도 후 성공할 가능성이 높다. 현재는 에러가 catch되어 false를 반환할 뿐 재시도가 없다.

단기 개선 (1주 이내)#

• lib/cupix/cron/record.rb:9,13,33 — cron 경로에서도 flushing_geo_coordinate_locked?를 확인하여 이미 진행 중인 flush가 있으면 skip하도록 수정. 현재 cron은 Redis lock을 무시하고 직접 flush_geo_coordinate를 호출하여 동시 실행 가능성을 높인다.
• FlushRecordGeoCoordinateWorker (line 23)에서 lock 확인과 lock 설정 사이의 race condition 방지를 위해 Redis SET NX (atomic lock) 패턴으로 전환 고려.

장기 개선 (재발 방지)#

• flush_geo_coordinate에서 S3 upload와 update 호출을 분리하여 S3 upload가 완료된 후에만 짧은 트랜잭션으로 update를 수행하는 구조로 변경. 현재도 auto-commit 모드이므로 update 자체는 짧은 트랜잭션이지만, 다수 worker가 동시에 같은 행을 update하려는 경합은 근본적으로 줄여야 한다.
• Sidekiq의 unique_until 또는 sidekiq-unique-jobs gem으로 동일 record_id에 대한 중복 flush worker enqueue를 방지하는 것이 가장 효과적이다.

Monitoring#

추가할 메트릭/알림:

service:cupixworks-worker status:error "Lock wait timeout"

• 5분 내 3건 이상 발생 시 알림 설정 (현재 2건으로 낮은 빈도지만 PullTaskWorker 등 다른 worker로의 확산 모니터링 필요).

service:cupixworks-worker "flush_geo_coordinate" "begin" | stats count by @record.id

• 동일 Record ID에 대한 동시 flush 실행 빈도 모니터링.

Risk Assessment#

• Risk level: medium
• 예상 복잡도: standard