RCA: Editing split failed — Mysql2::Error::TimeoutError: Lock wait timeout exceeded

Overview#

What Happened#

2026-07-18 21:33 KST에 cupixworks-worker의 EditingSplitWorker#perform이 Cupix::EditingSplitService#do_split! 마지막 단계에서 Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction으로 실패했다. 서비스 로그를 보면 두 개의 split 그룹 재할당(reassign)이 정상적으로 끝났고, 원본 editing 의 통계를 갱신하는 세 번째 트랜잭션(update_editing_stats)이 시작된 뒤 약 52초간 진행되지 못하다가 InnoDB row-lock 대기 한도(기본 50초)에 걸렸다. 1건만 관측되었지만 Sidekiq retry: 2 정책에 의해 재시도되므로 사용자 영향은 제한적이다.

Quick Facts#

Affected Teams#

Timeline#

1. 2026-07-18 21:30:53 KST — Cupix::EditingSplitService#compute_split_groups 완료 (task grouping, geo clustering).
2. 2026-07-18 21:31:15 KST — 첫 번째 split 그룹: create_split_editing + reassign_editing_entities 시작.
3. 2026-07-18 21:31:49 KST — 첫 번째 그룹 Editing entities reassigned (task-level) result.
4. 2026-07-18 21:31:55 KST — 첫 번째 그룹 Split group processed.
5. 2026-07-18 21:32:09 KST — 두 번째 split 그룹: create_split_editing + reassign_editing_entities 시작.
6. 2026-07-18 21:32:21 KST — 두 번째 그룹 Editing entities reassigned (task-level) result.
7. 2026-07-18 21:32:29 KST — 두 번째 그룹 Split group processed, 이어서 Updating original editing stats for first group.
8. 2026-07-18 21:32:33 KST — Updating editing stats (task-based) 로그 (원본 editing 의 마지막 트랜잭션 진입).
9. 2026-07-18 21:33:25 KST — Split lock release attempt 및 Editing split failed: Mysql2::Error::TimeoutError: Lock wait timeout exceeded. (21:32:33 이후 약 52초 → InnoDB innodb_lock_wait_timeout 기본 50초와 일치)
10. 2026-07-18 21:33:57 KST — 후속 Split entry / Split skipped (not splittable) 로그. Sidekiq retry 로 재실행되었으나 이미 split 완료 상태로 인식되어 no-op.

Error Log#

Datadog Logs

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

Impact#

• Service: cupixworks-worker
• 발생 횟수: 1
• 최초 발생: 2026-07-18 21:33 KST
• 최근 발생: 2026-07-18 21:33 KST

Sidekiq retry: 2 정책상 자동으로 두 번 재시도되며, 재시도 시 cycle_state_created? / splittable? 가드로 인해 이미 split 이 완료된 editing 은 no-op 처리된다 (editing_split_service.rb:47-63). 사용자 노출 영향은 낮지만, Phase 4 reconcile 및 마지막 stats update 가 트랜잭션 롤백되었기 때문에 원본 editing 의 stat_total_entities 가 split 이전 값으로 유지되어 통계가 일시적으로 왜곡될 수 있다.

Root Cause Summary#

Cupix::EditingSplitService#do_split! 는 하나의 editing 을 여러 그룹으로 쪼갤 때 그룹마다 별도의 ActiveRecord::Base.transaction 을 열어 EditingEntity, ElementTrace, Element 행 수천 건을 update_all 로 재배치한다. 마지막에는 원본 editing 자체의 통계를 갱신하는 세 번째 트랜잭션(editing_split_service.rb:206-212 → update_editing_stats at editing_split_service.rb:970-996)이 열린다. 21:32:33 KST 에 이 마지막 트랜잭션이 시작된 뒤, 동일 editing_id / level_id / record_id 를 다루는 다른 워커(같은 시간대에 siteinsights 관련 워커 다수가 활성 상태였음) 가 획득해 둔 InnoDB row lock 이 해제되기를 기다리다가 MySQL 기본 innodb_lock_wait_timeout (50초) 을 초과해 실패했다. Redis 기반 editing_split:<id> split lock 은 같은 editing 의 중복 split 만 막을 뿐 DB row lock 은 보호하지 못한다.

Technical Analysis#

Code Path#

• Entry point: app/workers/editing_split_worker.rb:5 — EditingSplitWorker#perform
• Split orchestrator: app/services/cupix/editing_split_service.rb:30 — split!
• Redis 분산락 획득: app/services/cupix/editing_split_service.rb:65-73
• Group-per-transaction 재배치: app/services/cupix/editing_split_service.rb:158-193
• Failure point: app/services/cupix/editing_split_service.rb:206-212 — 원본 editing 의 마지막 stats-update 트랜잭션
• 실제 UPDATE: app/services/cupix/editing_split_service.rb:990 — editing.update!(stat_total_entities: element_count)

Worker 진입점:

class EditingSplitWorker
  include Sidekiq::Worker
  sidekiq_options queue: :default, retry: 2

  def perform(editing_id)
    Cupix::Logger.info('Starting editing split', class: self.class.name, function: __method__, editing_id: editing_id)

    ::Cupix::EditingSplitService.new(editing_id: editing_id).split!

    Cupix::Logger.info('Editing split finished', class: self.class.name, function: __method__, editing_id: editing_id)
  rescue StandardError => e
    Cupix::Logger.error("Editing split failed: #{e.message}", class: self.class.name, function: __method__, editing_id: editing_id)
    raise
  end
end

문제의 마지막 트랜잭션 블록 (그룹마다 트랜잭션이 이미 여러 번 커밋되었지만, 원본 editing 의 통계 갱신은 별도 트랜잭션):

ActiveRecord::Base.transaction do
  if first_group[:element_ids].present?
    update_editing_stats_by_element_ids(editing, first_group[:task_ids], first_group[:element_ids])
  else
    update_editing_stats(editing, first_group[:task_ids])
  end
end

update_editing_stats 자체는 무거운 집계 쿼리 + editing.update! (editings 테이블 row lock 취득) 를 수행한다. 이 쿼리들은 editing.id 를 통해 다른 워커들이 자주 잡는 행에 접근한다:

def update_editing_stats(editing, remaining_task_ids)
  element_count = ::ElementTrace.joins(:element)
                                .where(task_id: remaining_task_ids, editing_id: editing.id)
                                .untrashed
                                .merge(::Element.untrashed)
                                .distinct.count(:element_id)
  et_count = ::ElementTrace.joins(:element)
                           .where(task_id: remaining_task_ids, editing_id: editing.id)
                           .untrashed
                           .merge(::Element.untrashed)
                           .count
  before_stat = editing.stat_total_entities
  Cupix::Logger.info('Updating editing stats (task-based)',
                     class: self.class.name,
                     function: __method__,
                     editing_id: editing.id,
                     remaining_task_ids: remaining_task_ids,
                     element_count: element_count,
                     et_count: et_count,
                     before_stat: before_stat)
  editing.update!(stat_total_entities: element_count)
  ...

Redis-기반 split 락 (editing_split:<id>) 은 같은 editing 에 대한 두 개의 split 실행만 방지한다 — 다른 워커(예: CreateSitetrackEditingEntitiesWorker, EditingStateChangeWorker, 통계/CDC 인덱싱 워커) 는 이 락과 무관하게 같은 editing/level 행을 잠글 수 있다:

def acquire_split_lock(lock_key)
  return true if Rails.cache.is_a?(ActiveSupport::Cache::NullStore)

  @split_lock_token = SecureRandom.uuid
  acquired = Rails.cache.redis_instance.set(lock_key, @split_lock_token, nx: true, ex: SPLIT_LOCK_TTL)
  ...
  acquired
end

대조 참고: 같은 도메인의 CreateSitetrackEditingEntitiesWorker 는 task 단위 Redis 어드바이저리 락을 이미 사용하고 있으며, 락 획득 실패 시 warn 으로만 남기고 진행한다 — 즉, split 서비스 쪽에 방어 로직이 상대적으로 부족한 것이 대비된다:

if Time.current >= deadline
  Cupix::Logger.warn('task_assign lock wait timeout, proceeding without this lock',
                     class: self.class.name, function: __method__,
                     sitetrack: { id: sitetrack_id }, task: { id: task_id }, lock_key: key)
  return nil
end

Log Evidence#

Datadog query used:

service:cupixworks-worker @class:"Cupix::EditingSplitService"
Time: 2026-07-18T12:20:00Z → 2026-07-18T12:40:00Z

핵심 로그 시퀀스 (모든 시각은 KST):

21:30:53  info   Task grouping complete                 (Cupix::EditingSplitService#compute_split_groups)
21:30:53  info   Processing split group                 (do_split!, group_index=1)
21:31:15  info   Created split editing                  (create_split_editing)
21:31:15  info   Reassigning editing entities (task-level)   (reassign_editing_entities)
21:31:49  info   Editing entities reassigned (task-level) result
21:31:55  info   Split group processed                  (group_index=1)
21:32:09  info   Created split editing                  (2nd group)
21:32:09  info   Reassigning editing entities (task-level)   (2nd group)
21:32:21  info   Editing entities reassigned (task-level) result
21:32:29  info   Split group processed                  (2nd group)
21:32:29  info   Updating original editing stats for first group   (do_split!)
21:32:33  info   Updating editing stats (task-based)    (update_editing_stats)   ← 마지막 트랜잭션 진입
21:33:25  info   Split lock release attempt             (release_split_lock, ensure 절)
21:33:25  error  Editing split failed: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction

주목할 갭: 21:32:33 → 21:33:25 = 52초. update_editing_stats 안에서 editing.update! 완료 로그(Editing stats updated (task-based) result, editing_split_service.rb:991-995)가 없다. 즉 로그가 남긴 시점은 UPDATE 이전이며, 이후 52초 대기 → InnoDB innodb_lock_wait_timeout 기본 50초를 넘어선 시점에 예외 발생, ensure 절이 실행되어 release_split_lock 로그가 21:33:25 에 함께 남음.

주변 시간대의 관련 워커 활동 (같은 시간대 시스템 부하 증거):

21:32:24  error  batch_pull! error on batch arn:aws:ecs:us-west-2:... AwsTask#batch_pull!  (다수)
21:33:12  error  flush_geo_coordinate ... Failed to open TCP connection to s3.me-south-1  Record#flush_geo_coordinate
21:33:29  error  failed to get captured area - error: 503 Service Unavailable             Cupix::VoxelService#captured_area!

같은 도메인(siteinsights/geo) 워커들이 활성이며, split 이 진행되는 동안 동일 facility/level 의 EditingEntity/Editing 행 lock 을 얻고 있었을 개연성이 높다.

과거 14일 Editing split failed 발생 이력:

2026-07-09 ~ 2026-07-17  error  Editing split failed: Waited 7 sec, 0/10 available   (다수, ActiveRecord::ConnectionTimeoutError)
2026-07-18 21:33         error  Editing split failed: Mysql2::Error::TimeoutError: Lock wait timeout exceeded   (본 건, 1회)

DB row-lock 타임아웃은 이번이 처음. 커넥션 풀 고갈(Waited 7 sec, 0/10 available) 문제는 별개의 이슈(재시도 성공률 · 커넥션 풀 사이즈)로 최근 반복되고 있다.

Hypotheses Considered#

Fix Recommendation#

즉시 조치 (Critical)#

• 직접 코드 변경 불필요 (자동 반영 대상 아님): 이번 실패는 단일 이벤트이며 Sidekiq retry: 2 로 자동 복구된다. 다만 원본 editing 의 stat_total_entities 가 split 이전 값으로 유지되므로, editing_id 를 특정한 뒤 관계자가 통계 재계산 여부만 수동 확인 권장.
• 재발이 관측될 경우에만 아래 단기 개선을 시작한다. 재현·현상 확인이 되지 않은 상태에서 트랜잭션 구조를 바꾸면 다른 회귀(예: update_editing_stats_by_element_ids 의 orphan reconcile 순서)를 유발할 수 있다.

단기 개선 (1주 이내)#

• app/services/cupix/editing_split_service.rb:206-212 의 update_editing_stats 트랜잭션 진입 전에 InnoDB row-lock 대기 한도를 세션 레벨로 낮춰 fail-fast 하게 만든다: ActiveRecord::Base.connection.execute("SET innodb_lock_wait_timeout = 10") 후 rescue → raise Sidekiq retry 로 넘겨 재시도가 빠르게 순환하도록. 참고: CreateSitetrackEditingEntitiesWorker#_acquire_task_lock 이 동일한 fail-fast 패턴을 이미 사용.
• Mysql2::Error::TimeoutError 를 명시적으로 rescue 하여 warn 으로 로깅하고 Sidekiq 에 다시 raise (재시도는 그대로 두되 error 레벨 알람을 억제). 위치: editing_split_worker.rb:11-14. 주의: 넓게 rescue StandardError 를 warn 으로 낮추지 말고 Mysql2::Error::TimeoutError 만 분리.
• editing.update!(stat_total_entities: ...) 를 트랜잭션 외부에서 낙관적 재시도(with_advisory_lock 또는 ActiveRecord::Base.transaction(requires_new: true) + retry) 로 감싸 lock 경합 시 backoff 하도록 변경 검토.

장기 개선 (재발 방지)#

• EditingSplitService 전체를 editings.id 단위의 DB 어드바이저리 락(GET_LOCK('editing_split:<id>', 30)) 뒤에 배치하여, 같은 editing 을 건드리는 모든 워커가 순서를 지키도록 도메인 락 계약을 통일. 현재 Redis TTL 락은 자기-중복만 방지하고 타 워커와의 순서를 강제하지 못한다.
• Phase 4 reconcile 을 별도 Sidekiq 잡으로 분리해 split 배치 트랜잭션 길이를 짧게 유지. 현재 do_split! 는 그룹 재할당(수천 rows) + Phase 4 (reconcile_scope_ids + sibling_scope_ids 단위의 EE trashing/synthesizing) 를 이어 실행하며 총 소요 2분+.
• 통계 갱신(stat_total_entities) 을 editings 컬럼 대신 카운터 캐시/서브쿼리로 대체 검토 — 통계 컬럼이 있어 매 split 마다 원본 행을 UPDATE 해야 하는 것이 근본 경합 원인.

Monitoring#

Datadog dashboard timeseries widget 용 쿼리 (모두 count/sum 스타일):

sum:trace.sidekiq.job.errors{service:cupixworks-worker,resource_name:EditingSplitWorker}.as_count()

logs("service:cupixworks-worker \"Editing split failed: Mysql2::Error::TimeoutError\"").index("*").rollup("count").by("env")

logs("service:cupixworks-worker @class:\"Cupix::EditingSplitService\" \"Split lock release attempt\"").index("*").rollup("count").by("env")

Sidekiq metric:

sum:sidekiq.job.duration{service:cupixworks-worker,job_class:EditingSplitWorker}.rollup(avg, 300)

임계값 제안: 시간당 EditingSplitWorker 의 Mysql2::Error::TimeoutError 카운트가 5건 이상이면 warn, 20건 이상이면 error 알람. 또한 editing_split_service.rb:990 UPDATE 소요 시간을 tracing span 으로 명시 (ddtrace custom span) 하는 방안도 검토.

Risk Assessment#

• Risk level: low (현 시점 1건, Sidekiq retry 로 자동 복구, 사용자 데이터 손상 없음)
• 예상 복잡도: standard (단기 개선 항목은 트랜잭션 경계·rescue 좁히기 · 세션 변수 조정 정도이며 관련 스펙 조정이 필요)