Skip to content

MeshNodeStreamCache: a package install's N compile-state satellite writes queue behind portal/nodeops and expire at their 5/10/20/30 s bounds on a slow VM — the Plugins gate's per-package time triples and the shard is cut at its cap #4141

Closed as duplicate

Description

@rbuergi

Symptom

On MeshWeaver.Plugins main, 2026-09-13, the test-repos / Gate shard 1/1 job (this repo's node-repo-gate.yml, one shard, 63→69 packages) was cut at its 30-minute cap on 4 of 6 consecutive full-set runs — 34729366478, 34731917156, 34733332465, 34739426546 (each ends 30:16–30:20 after the shard's own started_at) — while the other two, on the SAME resolved platform set (core a4d12f6a3) and the same content, finished in 10:02 (34730209730) and 14:44 (34733718196). Plugins mitigates with shards: 4 (Systemorph/MeshWeaver.Plugins#1765); this issue is the core half.

Measured: slow, not stuck — the time is expired bounds in MeshNodeStreamCache / PatchAck

The cut run had installed 64 of 69 packages, progressing at a uniform 2–3× the green runs' per-package time (Hosting 136 s vs 67 s, RolePlay 129 vs 42, Signature 116 vs 51, Chess 110 vs 38). Counting the warning shapes in the 14:44 log vs the cut log:

warning bound green (14:44) cut (30:18)
[UpdateQueue] ADVANCE_WITHOUT_HANDOFF … the owner never acknowledged this write inside the bound 5 s 19 76
[PatchAck] FLUSH_OUTLIVED_BOUND … the merge committed and is acked as such 10 s 7 26
[UpdateQueue] FAILED … MeshNodeStreamException: MeshNode Unknown at '<T>/_Activity/compile-state': TimeoutException 20 s 0 16
[UpdateQueue] FAILED path=Hosting/InstanceAction … TimeoutException: Update aborted: no initial state arrived 30 s 0 6
[STALE-CALLBACK] … pending > 30000ms (CreateOrUpdateNodeRequest@portal/nodeops, SubscribeRequest@Hosting/InstanceAction) 30 s 0 25
[CompileStateMirror] <T>: satellite write failed (state stays on the node; next change retries) — 0 15

SLOW_DISPATCH totals: SetCurrentRequest on sync/* hubs 553 s / 849 dispatches (max 17 s) on the green run vs 1966 s / 1060 (max 78 s) on the cut run; CreateNodeRequest on portal/nodeops-… avg 0.46 s → 1.05 s per dispatch (765 → 752 dispatches, 355 s → 790 s).

109 of the 115 expiries are on five packages — Hosting (16 NodeTypes), Signature (4), RolePlay (4), Chess (3), Edu (11) — i.e. the ones with the most types. The shape: when a package installs, every NodeType's CompileStateMirror writes its <Type>/_Activity/compile-state satellite; those writes queue behind the same serialised portal/nodeops hub as the package's node creates, and once a nodeops dispatch costs ~1 s (a slow hosted VM; 4 vCPU) the queue crosses the 5 s handoff bound, then the 10 s flush bound, then the 20 s stream bound; each expiry retries ("next change retries"), which lengthens the queue for the next type. The green/cut split is bimodal because which hosted VM a job lands on is random — this is MeshWeaver#2543's tax, seen from its cliff edge.

What is being asked

Not a bigger bound (each of these is already a bound that expired) and not a Plugins change (shards: 4 only stops paying the tax serially). The question is why a compile-state satellite write needs a 20 s stream timeout to fail under a busy nodeops hub, and whether N satellite writes per package install need to be N serialised nodeops round-trips at all — e.g. coalescing a package's compile-state writes, or giving _Activity/compile-state a path that does not queue behind content creates. A fix should show, on a Plugins full-set gate log, the ADVANCE_WITHOUT_HANDOFF / FLUSH_OUTLIVED_BOUND counts staying near the green run's (19 / 7) on a slow VM, not the cut run's.

Where the evidence lives

Analysis commands and the per-run table: MeshWeaver.Plugins .claude/skills/ci-policy/SKILL.md, section "The gate's 30-minute cap, measured 2026-09-13". Job logs: gh api repos/Systemorph/MeshWeaver.Plugins/actions/jobs/103682925570/logs (cut) vs the shard job of run 34733718196 (green).

🤖 Generated with Claude Code

https://claude.ai/code/session_01J9cAS8qpcEiQhfDJ2D2zFk

Activity

  1. rbuergi commented on Sep 13, 2026

    @rbuergi
    ContributorAuthor

    Folded into #2543 as its measurement — the analysis of this run's 25 [STALE-CALLBACK] records, the by-design/by-accident answer for the portal/nodeops serialisation, and the two instruments the next cut run will print are in the 2026-09-13 comment on #2543. Short form: nodeops's own turn is 3–5 ms in 21 of 25 records; the 3–25 s is the compile-state satellite write's verdict, and the reply then never reaches a NodeType hub whose pump is not taking turns (SubscribeRequest at depth=1 for 31+ s, pendingWork=316). Parallelising nodeops would not move these numbers; the target hub's held turn is what the new target pump now: line (#4154) will name.

  2. rbuergi commented on Sep 13, 2026

    @rbuergi
    ContributorAuthor

    Closing: folded into #2543 as its measurement (2026-09-13 comment there carries the STALE-CALLBACK analysis and the instruments). The gate-side time sinks measured today landed separately: #4169 (ListChildPaths children index, SlowDispatch bound, installer placeholder scope) and #4177 (gate-quiet), both on main and in platform set 3.0.0-ci.8484.

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