fix(routing): the saturation report prints the gauge that can see the wait it names by rbuergi · Pull Request #5162 · Systemorph/MeshWeaver

rbuergi · 2026-09-21T22:47:36Z

Addresses the instrument root shared by #5018 and #5118. 🚨 It does not fix either ticket — it makes them decidable, which all three consolidations named as the prerequisite. Both stay open.

What the defect is

Not a bound that is too small, and not a stuck leg. The saturation report printed the one pool gauge that is blind to the cause the line itself names.

RoutingGrain.ReportSaturation's leading hypothesis is the pre-subscribe ThreadPool wait, in its own words:

"A slot is held from dispatch until the leg terminates, INCLUDING the unbounded wait for a ThreadPool thread before the leg's own timeouts start, so a CPU-starved silo raises this with nothing stuck."

It then printed routingPool.CurrentInFlight. In IoPool, _inFlight is incremented only after _gate.WaitAsync has granted a slot and released as soon as source.Subscribe(observer) returns — so it counts the subscribe prologue and nothing else. A leg still waiting for a thread has not reached it; a leg past its subscribe, awaiting its own I/O, has already left it. Both are invisible, and two opposite diagnoses print the same number:

State	legs waiting for a slot	printed `routing pool subscribing`
every leg parked waiting for a ThreadPool thread — the named hypothesis	64	~0
every leg past subscribe, awaiting its own I/O — ordinary load	0	~0

All 19 log lines quoted verbatim across the three surviving tickets (10 in #5009, 6 in #5018, 3 in #5118) read 0, 1 or 2 in that field. So #5018's stated probable cause — ThreadPool starvation, confidence medium-high — is neither supported nor refuted by its own evidence.

The gauge that answers it already existed, was already implemented, and already stated the discriminator in its own XML doc:

"A depth that stays high while CurrentInFlight sits at the cap is a pool whose cap is the constraint; a depth that stays high while it does NOT is work that has not reached the gate — a thread shortage, not a slot shortage."
— IIoPool.CurrentlyWaiting

It was not printed. Nothing had to be measured on a pod to learn this; it was two files apart.

The second half: load vs. a leaked slot needed TWO samples

The line's advice for that is "a later line with a HIGHER episode on this activation means this episode drained" — sound, and it needs a second sample, while the incident filer files per sample. That is why #5003, #5014 and #5134 each captured a crossing that "excludes nothing": simultaneously the most alarming reading available and completely inconclusive. No event-driven report can state an absence.

An age answers it in one line. RoutingQuiescence already tracked every in-flight leg under a label precisely so a leg that fails to land can be named rather than counted (#2833); it did not record when each was accepted.

The fix

Two readings added to the same line, both from state the process already holds:

… routing pool subscribing 0, waiting for a pool slot 63;
  oldest leg in flight 1247031 ms — stream-routed → cache/… (delivery …). …

waiting for a pool slot — IIoPool.CurrentlyWaiting. Already on the interface with a default, so no interface member is added and no implementer is obliged.
oldest leg in flight — RoutingQuiescence.OldestInFlight(). TrackedLeg gains a Stopwatch.GetTimestamp() (monotonic, never a wall clock — this is an elapsed time on one process), and the reading returns the minimum with its label.

🚨 No bound moves. SaturationThreshold (64, still a log gate and nothing else), the routing IIoPool cap (256, measured: IoPoolOptions.Routing = 256), PodHubGrain's non-reentrancy, and every timeout are untouched. No retry, watchdog, poller or timer is added — RoutingQuiescence deliberately has none, and this reads the state it already keeps. Nothing is suppressed and no log level changes: the crossing stays Critical and the drained line stays Warning for the reason already documented there (a Critical "cleared" line would file an incident for a recovery and invert the signal).

🚨 Why the oldest leg is a composed phrase and not a number. Its two "no reading" cases are not zero. A sentinel of -1 or 0 is exactly the shape that reads as "the oldest leg is brand new" — the opposite of what it means — so none in flight and not tracked on this host are printed as words.

Registration checked, not assumed: quiescence is resolved with GetService, so an unregistered host would make this inert. OrleansServerRegistryExtensions calls services.AddRoutingQuiescence() unconditionally, and it registers the singleton — so the reading is live on any silo host, not a mechanism with no adopters.

Cost: OldestInFlight() is O(in-flight legs) and is called from the latched branch, i.e. once per saturation episode and never per route — the same cost argument OrderedRouteDispatcher.QueueSnapshot() already makes on that turn, over ~the reporting threshold's worth of entries at the moment the report fires.

Controls — measured on both sides, including one that turned out VACUOUS

case	result
`TwoOppositePoolStates_PrintTheSameSubscribingCount_AndOnlyWaitingTellsThemApart`	63 legs parked at the gate vs. 64 past their subscribe: both print `subscribing` ≤ 2 — inside the range every production sample carried — while `CurrentlyWaiting` differs by 63
`OldestInFlight_SeparatesLoadFromALeakedSlot_InOneSample`	names the oldest leg, its age advances with real elapsed time, follows landings, null when idle
negative control — `OldestInFlight` returns the NEWEST (comparison inverted)	FAILS as it must: reports `leg-63` instead of `leg-0`
negative control — `OldestInFlight` returns the FIRST ENUMERATED entry, no timestamp compare	🚨 PASSES — so the test does not establish independence from enumeration order

That last row is the reason the test's comment says what it does not prove. My first version of this case used three legs and asserted "whatever order the concurrent registry enumerates in"; the control showed a ConcurrentDictionary keyed by an incrementing long enumerates in insertion order at this size, so the assertion was vacuous. Widening to 64 legs did not rescue it. The claim is now stated as what it is — the comparison is there because the collection does not guarantee that order, not because a test caught it — and the falsifiable property (direction of the reading) is controlled for instead.

Nothing sleeps: the parked leg is a volatile int under a bounded SpinWait.SpinUntil, released in a finally so a failing assertion cannot strand it, and a distinct timestamp is forced by spinning until the monotonic clock moves rather than by waiting a guessed interval. Waits are TestTimeouts values; the [Fact(Timeout = 120_000)] literal is explained in the file (an attribute argument cannot be a property, and 30 s is the framework's own write bound, so a test bounded there always gives up one second before the framework can name the fault).

The grouping — this is the other half of the change set, and it is a result in itself

Re-read all six feature:routing-back-pressure / area:orleans survivors against the code. No further dedup is supportable, and four of the six have the causal arrow the other way round.

#	verdict
#5009 (sev:H)	the one genuine routing defect; fixed by #5151, awaiting production verification
#5018	root not establishable from its evidence — the gap this PR closes. Stays open
#5118	the alert is not firing on a healthy state; it is firing on one it cannot classify, so raise-the-threshold / demote-severity / auto-resolve are all refused. Stays open
#4824	heap exhaustion; routing is only where it surfaced. Must not be folded — its own stated root has no issue at all, so it is the sole record
#4886	occurrence 2 is the same event as #4824 (same pod, 06:29:21Z inside 06:28:25–06:31:04Z) ⇒ a full blocking GC. Other two unattributed
#5037	Orleans runtime placement on a stalled pool; deliberately not folded into #4886 (different log site, namespace, day; no measured stall in its window)

72 tickets were already folded by hand into #5009 and #5018 — these six are the survivors, and the log site is a magnet because a saturation gauge rises whenever the process loses CPU or heap, whatever the cause. "N tickets agree" is not evidence of a shared cause when the thing they agree on is a symptom gauge.

Also in this change set

Doc/Architecture/ReadingARoutingSaturationReport (new) — which number answers which question, the two opposite pool states, the oldest-leg discriminator, the three verdicts at one log site, and a reading order. Linked from LogWatchTriage (where a triager meets the line) and reciprocally from OrderedRouteChannels.
ReadingCiSignals, two reader rules. (1) The sanctioned instance of "a green gate answering with evidence it did not produce": on sha cb8a9b8fd6fe0ac9f9d824f1e8be8db56463fc13, MeshWeaver Build and Test reports success in 19 min 40 s (merge_group #13632, all six shards ran) and success in 3 min 31 s (push #13634, green-tree reuse, every shard skipped) — same workflow, same commit, indistinguishable at the rollup, with actions/runs/<id>/jobs as the one call that separates them. (2) mergeable_state: clean + auto_merge: false is a two-pole ambiguity — arming consumed on queue entry vs. arming lost — byte-identical over REST, separable only by the merge-queue entry list, and with stale gh-readonly-queue refs (pr-2850, pr-2941, pr-4150, …) ruled out as a proxy. Both measured tonight; the second was found by a session whose own PR was queued and so could not push it.

Local verification

dotnet build -c Release -warnaserror, 0 Error(s) / 0 Warning(s) on MeshWeaver.Hosting.Orleans, MeshWeaver.Hosting.Orleans.Test, MeshWeaver.Documentation.Test.

suite	result
`MeshWeaver.Hosting.Orleans.Test` (full)	308 / 308, 0 failed — the only suite that exercises this code through a real cluster
`DocumentationLinkIntegrityTest` + `TestTimeoutLiteralRatchetGuard`	4 / 4, 0 failed — the new `120_000` literals are outside the ratchet's regex by design, so its baseline is untouched

Pairs-with: none — no public type or member is removed. The only public-surface change is an ADDED method (RoutingQuiescence.OldestInFlight); TrackedLeg is private and InFlightSample's signature is unchanged.

Refs #5018, #5118, #5009, #4824, #4886, #5037.

Review round

One finding, taken — and the interesting part is that the obvious fix would not have closed it.

The parked leg discarded SpinWait.SpinUntil's result and called OnCompleted() either way, so a park that merely EXPIRED was indistinguishable from one that was RELEASED. That matters because the park is the starved shape: every reading in it is only about a starved pool if that head leg really held the pool's one slot for the duration.

Faulting the observable is necessary and not sufficient. The subscriptions are Subscribe(_ => { }, _ => { }), and that error arm is deliberate — 63 of these legs are cancelled at their gate wait when the pool drains, and the test must not red on expected teardown. So an OnError from the parked leg would have been swallowed by the very arm that exists for the cancelled ones, and the finding would have read as fixed with the hole still open.

So both halves: the spin's result now faults with a message naming the park as the subject, and the expiry is recorded in a flag an assertion reads. A volatile int rather than the Exception itself, because the write happens on a pool thread and the read on the test thread — an unsynchronised reference read may never observe it. That is also the shape the house prescribes for a release into a deliberately parked worker.

The broad catch (Exception ex) { observer.OnError(ex); } went with it: the only call in that delegate is a Volatile.Read predicate, so the catch could not fire and was a swallow-shaped construct earning nothing.

Re-verified after the change: -warnaserror clean, Orleans suite 308 / 308.
🤖 Generated with Claude Code

… wait it names The [ROUTE] back-pressure line named the pre-subscribe ThreadPool wait as its leading hypothesis and then printed IIoPool.CurrentInFlight, which IoPool increments only once the gate has GRANTED a slot and releases as soon as source.Subscribe returns — the subscribe prologue and nothing else. A leg still waiting for a thread has not reached it; a leg past its subscribe has already left it. So a starved silo and ordinary load print the same number, and all 19 log lines quoted across #5009, #5018 and #5118 read 0, 1 or 2 there. IIoPool.CurrentlyWaiting answers exactly this and already said so in its own XML doc ("a thread shortage, not a slot shortage"). It is now printed, as `waiting for a pool slot`. Second half: load-vs-leak needed TWO samples, because the line's discriminator is "a later line with a higher episode means this episode drained" while the incident filer files per sample — which is why #5003, #5014 and #5134 each captured a crossing that excludes nothing. No event-driven report can state an absence, but an AGE answers it in one line. RoutingQuiescence already tracked every in-flight leg under an identifying label (#2833) and now records when each was accepted, so the report carries `oldest leg in flight` with its label: every leg young is load, one leg minutes old is a slot that never came back. No bound moves — SaturationThreshold, the routing pool cap, PodHubGrain's non-reentrancy and every timeout are untouched; no retry, watchdog or timer is added, nothing is suppressed, and no log level changes. Registration checked rather than assumed: AddRoutingQuiescence() is called unconditionally, so the reading is live on any silo host. Controls measured on both sides. Inverting the comparison (report the NEWEST leg) fails as it must. A second negative control — returning the first enumerated entry with no timestamp compare — PASSES, so the test does not establish independence from enumeration order and now says so instead of claiming it; the first version of that assertion was vacuous. This does NOT fix #5018 or #5118. It makes them decidable, which all three consolidations named as the prerequisite; both stay open. Also records the grouping of all six routing tickets — no further dedup is supportable, and for four of the six the causal arrow runs the other way, a silo losing CPU or heap raising the routing gauge as a symptom — plus two CI reader rules measured tonight in ReadingCiSignals. Refs #5018, #5118, #5009, #4824, #4886, #5037. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Copilot

Copilot review overview

🟡 Changes recommended

The new test contains a SpinWait.SpinUntil(...) whose result is ignored, which can let the test complete successfully even when the intended “parked leg” condition was not actually maintained.

Get a fresh assessment by requesting another Copilot review.

Review effort: Lite
Findings: 1

Open (1)

Handle SpinUntil timeout instead of completing observable · New

What changed in this PR

Improves diagnosability of RoutingGrain saturation incidents by logging the pool gauge that can actually observe the pre-subscribe wait (IIoPool.CurrentlyWaiting) and by adding a single-sample discriminator for load vs. leaked slots (RoutingQuiescence.OldestInFlight()), with accompanying tests and documentation updates.

Changes:

Extend [ROUTE] Routing back-pressure logging to include CurrentlyWaiting and an “oldest leg in flight” phrase derived from RoutingQuiescence.
Enhance RoutingQuiescence tracking to record per-leg start timestamps and expose OldestInFlight().
Add a focused Orleans test + new/updated architecture docs explaining how to interpret the updated saturation report and related CI/merge-queue signals.

File	Description
test/MeshWeaver.Hosting.Orleans.Test/RoutingSaturationNamesItsOwnVerdictTest.cs	New test coverage for the two added discriminators (`CurrentlyWaiting`, `OldestInFlight`).
src/MeshWeaver.Hosting.Orleans/RoutingQuiescence.cs	Track per-leg timestamps and add `OldestInFlight()` to report oldest in-flight leg + age.
src/MeshWeaver.Hosting.Orleans/RoutingGrain.cs	Print `CurrentlyWaiting` and “oldest leg in flight” in the saturation report.
src/MeshWeaver.Documentation/Data/Architecture/ReadingCiSignals.md	Document “green but ran nothing” (reuse) and merge-queue ambiguity diagnostics.
src/MeshWeaver.Documentation/Data/Architecture/ReadingARoutingSaturationReport.md	New doc explaining how to read the updated routing saturation report and its verdicts.
src/MeshWeaver.Documentation/Data/Architecture/OrderedRouteChannels.md	Link to the new “Reading a Routing Saturation Report” doc.
src/MeshWeaver.Documentation/Data/Architecture/MergeQueue.md	Add pointer to the CI-signal interpretation guidance for queued vs stranded PRs.
src/MeshWeaver.Documentation/Data/Architecture/LogWatchTriage.md	Update triage guidance to read `oldest leg in flight` first and link to the new doc.
src/MeshWeaver.Documentation/Data/Architecture.md	Add the new routing saturation report doc to the architecture index.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

rbuergi · 2026-09-21T22:52:36Z

+        var parked = Observable.Create<Unit>(observer =>
+        {
+            try
+            {
+                SpinWait.SpinUntil(() => Volatile.Read(ref release) == 1, TestTimeouts.DefaultOuterBound);
+                observer.OnCompleted();
+            }
+            catch (Exception ex) { observer.OnError(ex); }
+            return Disposable.Empty;
+        });


Taken, and it is a real hole rather than a style point: a park that merely EXPIRED and a park that was RELEASED are different facts about the test's own subject, and completing on both makes the first indistinguishable from the second.

One thing worth adding, because the obvious fix is not sufficient on its own: faulting the observable is necessary but would still be swallowed. The subscription is Subscribe(_ => { }, _ => { }) — the error arm deliberately ignores terminals, because 63 of these legs are cancelled at their gate wait during teardown and the test must not red on that. So an OnError from the parked leg would go exactly nowhere.

So the fix is both halves: the spin's result is no longer ignored (it faults, with a message naming the park as the subject), AND the fault is captured where an assertion can see it, so a park that expired fails the test by name instead of being absorbed by the arm that exists for the cancelled legs. Without the second half the finding would have been 'fixed' while the hole stayed open — which is the more interesting version of what you caught.

Pushing that now.

The parked leg discarded SpinWait.SpinUntil's result and completed either way, so an expired park was indistinguishable from a held one — and every reading in the starved shape is only about a starved pool if that leg really held the only slot. Faulting alone would not have fixed it: the subscriptions use Subscribe(_ => { }, _ => { }) and that error arm is deliberate, because 63 legs are cancelled at their gate wait on drain and the test must not red on expected teardown. An OnError from the parked leg would have been swallowed by the very arm that exists for the cancelled ones. So the expiry is also recorded in a volatile int an assertion reads — volatile because the write is on a pool thread and the read on the test thread. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

github-actions · 2026-09-21T23:01:29Z

Test Results (shard 5)

0 files - 5 0 suites - 5 0s ⏱️ - 13m 42s
0 tests - 3 853 0 ✅ - 3 851 0 💤 - 2 0 ❌ ±0
0 runs - 3 857 0 ✅ - 3 855 0 💤 - 2 0 ❌ ±0