Skip to content

3.x.x: online migration 027 can deadlock with a serving rc.6 frontend, so r01-rc6-premigrate fails intermittently #789

Closed

Description

@kiwidream

r01_rc6_pair_serves_lands_and_restarts_while_3_1_migrates_its_database_to_31 (qbit-prism-dual-sim, CI job "Rust PRISM dual-writer scenarios (fast lane)") failed twice on Oct 27, on PRs that change no migration code. These are its only failures in the fast lane's last 23 completed runs, since #773 added it.

Both failures have one cause, in the server rather than the test. Migration 027 runs online while rc.6 frontends serve. Each ALTER takes an ACCESS EXCLUSIVE lock on its table and holds it until the migration commits. A frontend transaction that touches two of those tables in the opposite order closes a lock cycle. PostgreSQL breaks it only after deadlock_timeout (1 s), by aborting whichever side checks first.

Seen

Run 40517252132 (#786), 14:06 UTC: the migrate was the victim.

process 9638 detected deadlock while waiting for AccessExclusiveLock on relation 17613 after 1000.052 ms
DETAIL:  Processes holding the lock: 9545, 9575.
ERROR:  deadlock detected
DETAIL:  Process 9638 waits for AccessExclusiveLock on relation 17613; blocked by process 9545.
         Process 9545 waits for RowShareLock on relation 17731; blocked by process 9638.
  • 9638 is 027. It holds qbit_prism_templates (17731), which it alters at line 29, and waits for 17613, a table it alters later.
  • 9545 is node A's rc.6 frontend. Its transaction already holds 17613 and waits on SELECT true FROM qbit_prism_templates WHERE template_sha256=$1 FOR KEY SHARE.
  • 027 rolled back and never committed, so the scenario failed with 027 and 028 committed within 300s.

Run 40541342603 (#788), 16:33 UTC: a frontend statement was the victim.

ERROR:  deadlock detected
DETAIL:  Process 9642 waits for AccessShareLock on relation 17327; blocked by process 9682.
         Process 9682 waits for AccessExclusiveLock on relation 17385; blocked by process 9642.
         Process 9642: WITH stepped AS (SELECT a.fanout_txid FROM qbit_ctv_fanout_artifacts a JOIN qbit_pool_blocks b USING(block_hash) …
  • 9682 is 027. It holds qbit_pool_blocks, altered at line 22, and waits for qbit_ctv_fanout_artifacts, altered at line 28.
  • 9642 is node B's rc.6 CTV broadcaster. It has opened qbit_ctv_fanout_artifacts and waits for qbit_pool_blocks. It was aborted, and B logged CTV broadcaster attempt deferred error=… deadlock detected.
  • While 027 held qbit_pool_blocks through that 1 s wait, node A's rc.6 metrics collector hit its own 500 ms lock_timeout on the table: metrics database collection unavailable … canceling statement due to lock timeout. That failed the expectation no statement of node A's frontend was cancelled.
  • 027's statement took 1017 ms in all.

The logs are in each run's prism-dual-writer artifact, under target/dual-sim-reports/r01-rc6-premigrate/logs/. The PostgreSQL side is in postgres-a.log. The frontend side is in frontend-a.log and frontend-b.log.

Impact

Running 3.1's migrate against a database that rc.6 frontends still serve is the path #773 documents. It can:

  • Fail the migrate with deadlock detected, as in the first run. 027 uses IF NOT EXISTS throughout, so running it again is safe.
  • Abort a serving frontend's statement instead, as in the second run. In the first run, the frontend transaction would have been the one aborted if its deadlock check had run first.
  • Block readers for the whole cycle. For as long as the cycle lasts (up to deadlock_timeout), every reader of a table 027 has already altered is blocked. Anything with a shorter lock timeout fails.

Fix direction

  • Never wait for a lock while holding another. For example, take every lock 027 needs at the top of its transaction with one LOCK TABLE … IN ACCESS EXCLUSIVE MODE, under a lock_timeout far below deadlock_timeout and the collector's 500 ms. On a lock timeout, retry the transaction with backoff, as ledger/migration/partition.rs's with_lock_retries already does for 031's catalog steps.
    • With that change 027 gives up first in any cycle, and a frontend waits at most that timeout. Once 027 holds every lock, its catalog-only changes take milliseconds.
    • Reordering the ALTERs would fix only the cycles found so far.
    • 028 should be checked for the same pattern.
  • Widen the scenario's check. The cancellation expectation matches only canceling statement due to. Node B's deadlock detected in the second run passed it, so the check should match deadlocks too.

🤖 Generated with Claude Code

Activity

  1. kiwidream commented on Oct 27, 2026

    @kiwidream
    MemberAuthor

    Fixed by #791, merged into 3.x.x as 6c0af137 (a merge into 3.x.x does not auto-close). Before 027 runs, migrate now takes the lock of every table the pending 027 and 028 alter, and the migration history's lock, in one LOCK TABLE … IN ACCESS EXCLUSIVE MODE under a 100 ms lock and statement timeout. On a timeout or a deadlock abort it rolls the whole transaction back and retries with backoff (100 ms doubling to 2 s) under a 600 s deadline (migrate_schema_committed, crates/qbit-prism-server/src/ledger/migration/table_locks.rs). r01-rc6-premigrate's log check now also fails on deadlock detected (crates/qbit-prism-dual-sim/src/scenarios/rc6_premigrate.rs). Covered by ledger_postgres::premigrate_lock_order::migration_027_backs_off_instead_of_closing_a_lock_cycle_with_a_serving_frontend and the five gated table_locks::postgres_tests.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions