Reproduce checkpoint prepare stall during initial sync

XMLWordPrintableJSON

    • Type: Task
    • Resolution: Unresolved
    • Priority: Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Checkpoints
    • None
    • Storage Engines - Persistence, Storage Engines - Transactions
    • 238.744
    • SE Persistence backlog
    • None

      HELP-95844 saw a checkpoint prepare stall during initial sync. This ticket is to create a reproducer of this scenario so we can investigate further.

      Evidence/timeline gathered from HELP-95844

      Reconstructed from mongod logs, mongos logs and shard FTDC.

      Time (UTC) Source Event
      18:23 / 18:26 log Node restarted; resumes logical initial sync (memberState STARTUP2)
      21:39:49 log Begins cloning collection (target 57.5M docs)
      21:39 → 22:40 log/FTDC Clone steady ~1,700-2,000 docs/s; WT healthy (cache flat ~80%, dirty <2%, 4 evict workers)
      ~22:39:28 FTDC Eviction walk pins to 1 and stays (earliest anomaly; reporter's "just before marker A")
      22:39:31 (A) reporter Workload halt (Atlas metrics)
      ~22:39:46 (B) log/FTDC Next periodic checkpoint enters prepare and never completes (checkpoint prepare currently running = 1 from 22:39:47)
      22:39:47 → 22:41:11 FTDC Cache fill 80%→87.5%, dirty 0.3%→7.6%, monotonic; cloner still inserting ~2,000/s; eviction not yet aggressive
      22:40:23 log Last clone progress-meter advance (12%); inserts continue to ~22:41:11
      22:41:11 FTDC Last FTDC sample. serverStatus stops completing; writer frozen here
      22:41:12 log (WTCHKPT) Checkpoint prepare stuck 86 s, "gathered 1 dhandle, skipped N". No further checkpoint messages
      22:42:40 log serverStatus was very slow: 87,382 ms, all in the oplog section; this call started ~22:41:13 (Atlas monitoring agent), the only serverStatus to log completion (id 20499 x1)
      22:41:11 → 23:41:10 FTDC Frozen/stale samples: uptimeMillis pinned at one value (not advancing), so no new data collected
      23:42:55 log Last mongod log line. Full process hang
      12:10:59 log ***** SERVER RESTARTED *****; WT recovers from last clean checkpoint (logs 123-126), no corruption
      13:01 / 13:03 (D) log/reporter Pre-image truncation; VM replaced; workload recovers. Initial sync restarts from scratch

            Assignee:
            [DO NOT USE] Backlog - Storage Engines Team
            Reporter:
            Sean Watt
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated: