Skip to content

[MySQL] Checkpoint creation stalls on idle servers: heartbeat keepalive LSN is behind the last commit LSN #704

Description

@michaelbarnes

Background

This comes out of a PowerSync support case: a customer running Service 1.22.0 with a MySQL source and MongoDB bucket storage reported replication lag on a quiet test instance that never recovered on its own. Waiting did nothing, compaction did nothing, and only restarting the service cleared it. We root-caused it from their logs, then reproduced it in our support workbench against the pinned journeyapps/powersync-service:1.22.0 image, and verified the code is unchanged on current main.

Symptom

On an idle server (no writes arriving), the service logs this every ~30 seconds, indefinitely:

INF [powersync_1_429d] Waiting before creating checkpoint, currently at
0000000039489899|2e35321d-...:39489899|mysql-bin.000027|565835613 / 0.
Current state: {"snapshot_done":true,
"last_checkpoint_lsn":"0000000039489899|2e35321d-...:39489899|mysql-bin.000027|565836177", ...}

Note the signature: the current LSN and last_checkpoint_lsn share the same padded transaction id (39489899), but the current binlog offset (565835613) is behind the checkpoint offset (565836177).

Root cause

MySQL LSNs are strings compared lexicographically (for example canCheckpointState in modules/module-mongodb-storage/src/storage/implementation/CheckpointState.ts, which requires lastCheckpointLsn <= lsn). In modules/module-mysql/src/replication/zongji/BinLogListener.ts:

  • The GTID event handler builds currentGTID with the position of the GTID event, i.e. the start of the transaction.
  • The Xid handler builds the commit LSN from evt.nextPosition, i.e. the end of the transaction. That LSN becomes last_checkpoint_lsn.
  • Heartbeat keepalives re-send currentGTID.comparable, the stale start-of-transaction LSN.

So the moment the last transaction commits on a quiet server, every subsequent heartbeat presents an LSN that sorts below the stored checkpoint, and checkpoint creation is blocked until the next real transaction arrives. The same applies to the DDL auto-commit and non-transactional query commit paths in processQueryEvent.

Reproduction

Fully scripted in our workbench; the minimal manual version:

  1. Start the service (1.22.0 or main) with a MySQL source, let the snapshot complete
  2. Commit one transaction, then leave the server idle
  3. From the first heartbeat (~30s, KEEPALIVE_INACTIVITY_THRESHOLD = 30) onward, the service logs Waiting before creating checkpoint with the same transaction id and a smaller binlog offset than last_checkpoint_lsn
  4. A single new write unblocks it immediately

In our repro the commit stored offset 607 while every idle keepalive re-sent offset 276 for the same transaction, matching the customer's log pattern digit-for-digit at their offsets.

Impact

  • Blocked (empty) checkpoints and log spam on idle instances
  • Confusing for operators: it presents as stuck replication lag on quiet instances, and in this customer's case led to an unnecessary bucket storage volume deletion
  • The replication lag metric itself stays at 0 in this state (the last commit succeeded), so the noise is worse than the harm, but the checkpoint gate is genuinely closed until the next write

A fix PR follows shortly: all commit paths now advance currentGTID to the commit position, so keepalive LSNs are never behind the last checkpoint LSN.


🤖 AI disclosure: this issue was generated by Claude (via Claude Code). The investigation, reproduction, and write-up were produced by Claude working from the customer's logs, directed and reviewed by @michaelbarnes.

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