Skip to content

Compile: stop source discovery idling 90s on a missed Initial, and pin recursive compilation - #682

Merged
rbuergi merged 2 commits into
mainfrom
fix/compile-source-stall
Jul 27, 2026
Merged

rbuergi merged 2 commits into
mainfrom
fix/compile-source-stall

Conversation

@rbuergi

@rbuergi rbuergi commented Jul 27, 2026

Copy link
Copy Markdown
Contributor

The profile

Straight from the Store/Plugin compile activity node that preceded today's outage:

20:46:02.486  Invoking compiler…
20:47:32.673  Source query: … (all nine, one timestamp)
20:47:35.288  Compiled assembly written
phase time
source discovery 90.19 s
Roslyn compiling 30 files 2.6 s
write + release 0.2 s

97% of the compile was waiting, not compiling. And 90.19 s is 2 × SyncStreamOptions.HeartbeatInterval (45 s).

Root cause — a lost wakeup, not a lock

When the cached synced source query's subscription misses its Initial, nothing re-requests it. The read makes no progress until the sync stream's periodic heartbeat re-delivers content. Miss it twice and a 3-second compile takes a minute and a half — which is exactly how Store/Plugin blew the 60 s settle window and left every plugin root serving the "did not settle" fallback.

This failure mode has bitten before: one screen above the fix, an existing comment documents the identity-loss variant — "the source reads run unauthenticated and stall until the next 45s sync-stream heartbeat — the ~42s freeze." Same signature, different trigger.

The fix

Race the cached query against a direct, uncached mesh read of the same expanded queries:

  • the probe is subscription-delayed (3 s), so a healthy compile — cache hit or one cold storage read — never issues it and pays nothing;
  • a stalled compile answers in about a read instead of 45 or 90 seconds;
  • Amb takes whichever speaks first and drops the other;
  • when the probe wins it logs at Warning — "compiles are slow" was invisible until someone read microsecond timestamps out of an activity node.

The probe accumulates chunks rather than taking the first emission: a query's Initial arrives chunked, and a partial source set compiles wrong — the missing file surfaces as a phantom Roslyn error pointing at code that is perfectly fine.

Fully reactive: Defer / CombineLatest / Scan / Throttle / Take / Select / Catch. No await, no ToTask, no blocking bridge.

Recursive compilation tests

The incident ran through the cross-type path: Store/Plugin declares shared=@Store/Coupon/Source, shared=@Store/Order/Source, shared=@Store/BillingProfile/Source — which is what turns discovery into nine live queries. RecursiveCompilationTest pins both halves:

  • Expansion — a shared reference yields both the folder node and its subtree, for every referenced type; deterministic; no self-recursion; a non-shared type does not leak in; matching agrees with expansion (the compiler and the Sources menu use the same resolver).
  • Chunk accumulation — chunked Initial accumulates instead of truncating, re-delivery is idempotent, removal drops, empty/null changes are inert.

Worth stating plainly: these pass on main. The recursion is correctly specified — what failed is the execution of those queries stalling. The tests are there so a regression in either half is caught, and so the next person profiling a slow compile starts from a pinned contract.

Testing

644/644 Graph tests pass.

Follow-ups not in this PR

  • Why the Initial is missed in the first place (cold subscription racing the source-update burst) — this makes it survivable, it does not remove the race.
  • Per-stage compile timing in the activity log, so this is measurable without microsecond arithmetic.
  • A readiness gate / deploy-time precompile — worth revisiting after this, on real numbers: a 3 s compile changes that calculus completely.

🤖 Generated with Claude Code

…n recursive compilation

Profiled from the Store/Plugin compile activity log that preceded today's outage:

  20:46:02.486  Invoking compiler…
  20:47:32.673  Source query: … (all nine, one timestamp)
  20:47:35.288  Compiled assembly written

90.19s of source discovery. 2.6s of Roslyn. 97% of the compile was waiting, not
compiling — and 90.19s is 2 x SyncStreamOptions.HeartbeatInterval (45s).

That is a LOST WAKEUP, not a lock: when the cached synced source query's
subscription misses its Initial, nothing re-requests it, so the read makes no
progress until the sync stream's periodic heartbeat re-delivers content. Miss it
twice and a 3-second compile takes a minute and a half — which is how a type blew
the 60s settle window and left every plugin root serving the "did not settle"
fallback. The same signature is already documented one screen up in this file
("stall until the next 45s sync-stream heartbeat — the ~42s freeze") for an
identity-loss variant, so this failure mode has bitten before.

Fix: race the cached query against a direct, uncached mesh read of the SAME
expanded queries. The probe is subscription-delayed, so a healthy compile — cache
hit or one cold storage read — never issues it and pays nothing; a stalled one
answers in about a read instead of 45 or 90 seconds. Amb takes whichever speaks
first. When the probe wins it says so at Warning, because "compiles are slow" was
invisible until someone read microsecond timestamps out of an activity node.

The probe ACCUMULATES chunks rather than taking the first emission: a query's
Initial arrives chunked, and a partial source set compiles WRONG — the missing file
surfaces as a phantom Roslyn error pointing at code that is fine.

Fully reactive throughout: Defer/CombineLatest/Scan/Throttle/Take/Select/Catch. No
await, no ToTask, no blocking bridge.

Also adds RecursiveCompilationTest for the cross-type (shared=@Other/Source) path
that this incident ran through — Store/Plugin reaches into three other types, which
is what makes discovery nine live queries. It pins expansion (both folder and
subtree forms, every referenced type, deterministic, no self-recursion, matching
agrees with expansion) and chunk accumulation (chunked Initial accumulates,
re-delivery idempotent, removal drops, empty/null inert). Notably these pass on
main: the recursion is correctly SPECIFIED — what failed is the execution of those
queries stalling.

644/644 Graph tests pass.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Copilot AI review requested due to automatic review settings July 27, 2026 21:32
Self-review of the fix found a way to make things worse than the bug. Every leg of
the uncached probe degrades to an empty list on error, so a probe that hit a cold
partition or a permission wall would report "no sources", beat the cached query
after 3s, and compile the type against NOTHING — a green compile producing an empty
assembly, which is strictly worse than the 90s stall it exists to dodge.

The probe now stays silent unless it actually found sources; the cached query and
the outer Timeout decide from there. Pinned by EmptyDiscovery_IsNotAValidSourceSet.

645/645 Graph tests pass.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@rbuergi

rbuergi commented Jul 27, 2026

Copy link
Copy Markdown
Contributor Author

Reproduced on a warm, healthy mesh — one heartbeat, exactly

Triggered a compile of Store/Coupon on memex just now (site healthy, nothing wedged, cache warm). Its activity log:

21:35:47.712  Compile started for Store/Coupon
21:35:47.712  Invoking compiler…
21:36:32.909  Source query: … (all nine, one timestamp)
21:36:35.736  Compiled assembly written
21:36:35.972  end
phase time
source discovery 45.20 s
Roslyn compiling 23 files 2.83 s

45.20 s is one HeartbeatInterval (45 s), to within 200 ms. The outage compile was 90.19 s — two.

This settles two things:

  1. Not a cold-start artifact. A warm, healthy mesh pays a full heartbeat on every compile. The outage wasn't a freak event; it was this constant plus a 60 s settle window, which any type with enough sources will eventually cross.
  2. It's the cross-type path. Store/Coupon matched 23 Code nodes across four types (Store/Coupon, Store/Plugin, Store/Order, Store/BillingProfile) via shared= — nine expanded queries, which is why RecursiveCompilationTest in this PR pins that expansion.

Expected after this change: the probe answers at ~3 s (its subscription delay) instead of 45 s, so the same compile lands in about 6 s wall-clock — and the Warning line says the probe won, making the underlying lost-wakeup visible instead of silently costing 45 s a time.

I'll post the same measurement taken after deploy.

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR targets a production compile outage mode where source discovery can stall for ~90s when a cached synced query misses its Initial, by adding a delayed “direct/uncached” probe as a fallback and pinning recursive compilation behavior with new tests.

Changes:

  • Add a delayed, uncached IMeshService.Query-based source probe raced (Amb) against the cached synced source snapshot to avoid long idle waits on a missed Initial.
  • Add a pure accumulator (ApplyQueryChange) and a new test suite to pin recursive source-query expansion and chunked-Initial accumulation behavior.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 4 comments.

File Description
src/MeshWeaver.Graph/Configuration/MeshNodeCompilationService.cs Races cached source snapshot vs. delayed uncached probe; adds accumulator for chunked query changes.
test/MeshWeaver.Graph.Test/RecursiveCompilationTest.cs Adds tests for shared-source expansion and chunked Initial accumulation behavior.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment on lines +515 to +529
internal static ImmutableDictionary<string, MeshNode> ApplyQueryChange(
ImmutableDictionary<string, MeshNode> acc, QueryResultChange<MeshNode> change)
{
if (change?.Items is not { Count: > 0 } items)
return acc;
foreach (var node in items)
{
if (string.IsNullOrEmpty(node?.Path))
continue;
acc = change.ChangeType == QueryChangeType.Removed
? acc.Remove(node.Path)
: acc.SetItem(node.Path, node);
}
return acc;
}
Comment on lines +545 to +550
if (queries.Length == 0)
return Observable.Empty<IEnumerable<MeshNode>>();

var mesh = hub.ServiceProvider.GetService<IMeshService>();
if (mesh is null)
return Observable.Empty<IEnumerable<MeshNode>>();
Comment on lines +559 to +564
mesh.Query<MeshNode>(MeshQueryRequest.FromQuery(q))
.Scan(ImmutableDictionary<string, MeshNode>.Empty, ApplyQueryChange)
.Throttle(SourceProbeQuietWindow)
.Take(1)
.Select(map => (IReadOnlyCollection<MeshNode>)map.Values.ToList())
.Catch((Exception _) => Observable.Return<IReadOnlyCollection<MeshNode>>([]))))
Comment on lines +579 to +581
}))
.Catch((Exception _) => Observable.Empty<IEnumerable<MeshNode>>())
.DelaySubscription(SourceStallProbeDelay);
@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 3)

   12 files  + 1     12 suites  +1   4m 28s ⏱️ + 1m 56s
  974 tests +59    970 ✅ +59  4 💤 ±0  0 ❌ ±0 
1 037 runs  +59  1 033 ✅ +59  4 💤 ±0  0 ❌ ±0 

Results for commit 217f3f8. ± Comparison against base commit 7e2e1a4.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 4)

1 995 tests  +9   1 807 ✅ +9   5m 6s ⏱️ +9s
   12 suites ±0     188 💤 ±0 
   12 files   ±0       0 ❌ ±0 

Results for commit 217f3f8. ± Comparison against base commit 7e2e1a4.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 0)

959 tests  ±0   953 ✅ ±0   4m 54s ⏱️ +6s
  5 suites ±0     6 💤 ±0 
  5 files   ±0     0 ❌ ±0 

Results for commit 217f3f8. ± Comparison against base commit 7e2e1a4.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 2)

1 129 tests  ±0   1 026 ✅ ±0   5m 21s ⏱️ -8s
   10 suites ±0     103 💤 ±0 
   10 files   ±0       0 ❌ ±0 

Results for commit 217f3f8. ± Comparison against base commit 7e2e1a4.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 1)

1 183 tests  ±0   1 182 ✅ ±0   7m 2s ⏱️ -26s
   10 suites ±0       1 💤 ±0 
   10 files   ±0       0 ❌ ±0 

Results for commit 217f3f8. ± Comparison against base commit 7e2e1a4.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 5)

1 139 tests  ±0   1 138 ✅ ±0   6m 34s ⏱️ +19s
   12 suites ±0       1 💤 ±0 
   12 files   ±0       0 ❌ ±0 

Results for commit 217f3f8. ± Comparison against base commit 7e2e1a4.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results

   61 files  + 1     61 suites  +1   33m 29s ⏱️ + 1m 57s
7 379 tests +68  7 076 ✅ +68  303 💤 ±0  0 ❌ ±0 
7 442 runs  +68  7 139 ✅ +68  303 💤 ±0  0 ❌ ±0 

Results for commit 217f3f8. ± Comparison against base commit 7e2e1a4.

@rbuergi
rbuergi merged commit ee5f2a0 into main Jul 27, 2026
15 checks passed
rbuergi added a commit that referenced this pull request Jul 29, 2026
…synced query

A compile needs a POINT-IN-TIME snapshot of its sources. It was taking that snapshot
from the cached SYNCED query, which exists to deliver LIVE updates — a guarantee a
compile does not need and, on a large mesh, pays 45 seconds for.

Measured on memex, same box, same data, same four queries a Store/Coupon compile
issues:

    via IMeshService.Query (what MCP `search` uses)    ~0.25s   counts 16 / 4 / 1
    via the cached synced query (what compiles used)    45.20s

45.20s is one SyncStreamOptions.HeartbeatInterval to within 200ms: the synced
subscription misses its Initial and idles until the periodic heartbeat re-delivers.
Roslyn itself is 2.83s, so 97% of every compile was that wait — and types then
crossed the 60s settle window, which is how every plugin root came to serve the
"did not settle" fallback on 2026-07-27.

Everything else was eliminated by experiment BEFORE writing this, which is the part
the earlier attempts skipped:

  - the compile path itself     0ms discovery on a fresh mesh (issue #686)
  - topology                    0ms with ONE silo and with TWO (real AdoNet cluster,
                                both silos Active) — silo count is not the cause
  - scale / ~90 schemas         the same queries answer in 0.25s ON memex
  - the heartbeat schedule      #684 shipped and measured no change (48s → 57s)
  - pre-warming                 enabled on memex, degraded 7 of 16 roots, rolled back

So: direct read FIRST, synced query kept only as a fallback when the direct read
finds nothing. Never the other way round. #682 kept the cache primary and raced a
delayed probe against it — that probe never fired once in production, and this
ordering is exactly what removes the dependency on winning a race.

647/647 Graph, 8/8 Hosting.Monolith compile/pre-warm integration tests.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
rbuergi added a commit that referenced this pull request Jul 29, 2026
…synced query (#690)

A compile needs a POINT-IN-TIME snapshot of its sources. It was taking that snapshot
from the cached SYNCED query, which exists to deliver LIVE updates — a guarantee a
compile does not need and, on a large mesh, pays 45 seconds for.

Measured on memex, same box, same data, same four queries a Store/Coupon compile
issues:

    via IMeshService.Query (what MCP `search` uses)    ~0.25s   counts 16 / 4 / 1
    via the cached synced query (what compiles used)    45.20s

45.20s is one SyncStreamOptions.HeartbeatInterval to within 200ms: the synced
subscription misses its Initial and idles until the periodic heartbeat re-delivers.
Roslyn itself is 2.83s, so 97% of every compile was that wait — and types then
crossed the 60s settle window, which is how every plugin root came to serve the
"did not settle" fallback on 2026-07-27.

Everything else was eliminated by experiment BEFORE writing this, which is the part
the earlier attempts skipped:

  - the compile path itself     0ms discovery on a fresh mesh (issue #686)
  - topology                    0ms with ONE silo and with TWO (real AdoNet cluster,
                                both silos Active) — silo count is not the cause
  - scale / ~90 schemas         the same queries answer in 0.25s ON memex
  - the heartbeat schedule      #684 shipped and measured no change (48s → 57s)
  - pre-warming                 enabled on memex, degraded 7 of 16 roots, rolled back

So: direct read FIRST, synced query kept only as a fallback when the direct read
finds nothing. Never the other way round. #682 kept the cache primary and raced a
delayed probe against it — that probe never fired once in production, and this
ordering is exactly what removes the dependency on winning a race.

647/647 Graph, 8/8 Hosting.Monolith compile/pre-warm integration tests.

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
rbuergi added a commit that referenced this pull request Jul 29, 2026
Second half of unbreaking main. #690 (de86b03) made MeshWeaver.Hosting.Monolith.Test
exceed CI's 6m wall-clock cap (exit=124) on every run since it landed.

CI reports that cap as "likely fixture/init hang". It is not a hang — the suite
completes; it just got slower. Measured on one box, CompileLeafStabilityTest:

    before #690 (cached query primary)     4s
    #690 as merged (probe, then cached)   52s     ← 13×
    this change (true race)                4s

    full suite: 7m50s -> 3m13s (CI cap 6m)

WHY IT GOT SLOWER. #690 chained the direct probe ahead of the synced query with
Concat. Concat is SEQUENTIAL: the synced query is not even subscribed until the
probe COMPLETES. So every compile paid the probe's full latency up front — and the
probe cannot answer faster than SourceProbeQuietWindow, because each leg has to
watch its chunked Initial go quiet before it may emit. That is a ~1s floor per
compile that the previous code never paid: the probe was DelaySubscription'd and on
a healthy mesh never ran at all.

That floor lands on far more calls than "compiles". The disk cache is keyed by
effectiveLastModified, which comes from DiscoverSourceMaxLastModified ->
SnapshotSources — so source discovery runs BEFORE the cache can be consulted, and
a cache HIT pays it too. In a suite that touches the same NodeTypes repeatedly the
cache-hit path is the common case, which is why a 1s floor cost minutes.

Merge starts both sources NOW and FirstAsync takes whichever answers first, so:
  * healthy synced query  -> answers immediately, probe latency never on the path
  * stalled synced query  -> probe answers in a read + quiet window, not 45s
#690's production win is kept; neither source is privileged, so the fast path does
not depend on winning a race (#690's stated objection to #682).

Merging is safe precisely because of #690's own `.Where(count > 0)`: a probe that
finds nothing stays SILENT and completes, so it can never beat the cached query
with an empty set and compile against no sources. That filter is also the likelier
reason #682's probe "never fired" in production — not the 3s delay alone.

NOT done: shrinking SourceProbeQuietWindow to 50ms, which also takes 52s -> 7s.
That window exists so a chunked Initial can settle; the code's own comment warns a
partial source set "compiles WRONG (missing files -> phantom errors)". Nor raising
the 6m cap — the cap did not change, the compile path got 13x slower.

Verified: Hosting.Monolith.Test 419/421 in 3m13s (2 skipped, 0 failed), including
CompileSourceSnapshotWedgeTest which covers the stalled-snapshot path #690 exists
to fix; Graph builds clean under -c Release -warnaserror.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@rbuergi
rbuergi deleted the fix/compile-source-stall branch August 5, 2026 10:45
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants