Compile discovery costs ~45s on memex but 0ms on a fresh mesh — it is cold hub activation at scale, not the compile path #686

Activity

1. rbuergi commented on Jul 28, 2026

   

   rbuergi

   on Jul 28, 2026

   ContributorAuthor

   More actions

   Enabling the pre-warm on memex: tried, degraded the site, rolled back

   Sequence, 2026-07-28 ~05:25–05:40Z:

   1. Deployed 3.0.0-ci.1471 (= f359385, containing Pre-warm one NodeType at a time — 4-at-once is the storm that keeps boot warming disabled #687's concurrency-1 + 2s-stagger pre-warm). Verified 16/16 roots healthy on that image with the flag still OFF.
   2. Set PreWarm__DynamicTypes=true (confirmed present in the pod spec).
   3. ~4 minutes into the warm sweep: 7 of 10 sampled roots degraded — AgenticEngineering, Claims, Edu unreachable; Underwriting, Publish, Training, Pricing on the fallback overlay.
   4. Rolled back: unset the flag, scale-to-zero → 2. 16/16 healthy again.

   What this means

   Sequencing the warm-up is not sufficient. #687 was a real improvement — 4-at-once is measurably worse — but even one-type-at-a-time with a 2 s stagger is too much additional load on a mesh this size while it is also serving its own cold-start traffic. The warm sweep competes with exactly the activations it is trying to pay off.

   So the class summary's "ships disabled" is right for reasons beyond concurrency, and #687 should be understood as making the option less dangerous, not as making it safe to enable here.

   Caveat on the evidence

   I could not confirm the sweep was actually running: no DynamicTypePreWarmer log lines appeared on either pod, not even the disabled (…!= true) line that logs when the flag is off. The category appears to be filtered below Information in this deployment. So strictly, what is established is:

   enabling the flag correlated with rapid, reproducible degradation, and unsetting it plus a restart restored the site.

   Not established: that the warmer itself did the damage, versus the pod restart the set env triggered landing badly. Both restarts tonight that didn't have the flag recovered to 16/16 on their own, which points at the flag — but I want the weaker claim on record rather than the confident one.

   Recommended before anyone retries

   1. Raise DynamicTypePreWarmer logging so the sweep is observable (it is currently invisible in production, which is why this attempt yields correlation rather than causation).
   2. Cap the sweep — e.g. warm only the top-N most-requested types, or spread it over minutes rather than seconds.
   3. Retry on a single instance with the roots watched, as was done here, and expect to roll back.

   The underlying defect in this issue — cold cross-partition hub activation costing 45.20 s on memex versus 0 ms on a fresh mesh — remains the thing to fix. Pre-warming is a mitigation that this mesh currently cannot absorb.
2. rbuergi commented on Jul 28, 2026

   

   rbuergi

   on Jul 28, 2026

   ContributorAuthor

   More actions

   The variable my "fresh mesh" comparison never controlled: SILO COUNT

   The failing read says it in its own words:

   GetMeshNode('ACME/ProductLaunch') timed out after 60.0s — the owning per-node hub never
   answered the GetDataRequest. This is NOT 'node not found'.
   Target: NO LOCAL HUB at 'ACME/ProductLaunch' — it never activated here
           (or is owned by another silo), so no reply was ever going to be produced.
   

   "or is owned by another silo." My comparison was:

   	silos	discovery
   disposable mesh (Orleans__Clustering: "Localhost")	1	0 ms
   memex (memex-portal-deployment, 2 replicas)	2	45.20 s

   On one silo every hub is local, so a read can never miss. On two, a read for a node owned by the other silo has to be routed there — and if that routing does not happen for GetDataRequest, the reader waits its full budget and reports exactly the message above. That would explain, in one mechanism:

   • 0 ms versus 45.20 s discovery for the identical NodeType shape and image;
   • why the stall reappears after every deploy (ownership redistributes across the two silos);
   • why a second compile is fast (165 ms — by then the type is cached, no cross-silo read);
   • why TwoSiloRecycleConvergenceTest is one of the four main flakes, and why the flakes are all TimeoutException;
   • why cross-silo messagehub forwarding was visibly working in the outage logs (S10.244.4.102 → S10.244.2.97) while these reads still died: the forwarding path that works for hub messages may not cover this read.

   Why I am not testing it tonight

   Reproducing two silos locally needs a shared clustering provider rather than Localhost, and I am not going to guess at that config or run another experiment against memex — I have already caused two degradations there tonight (a compile storm while collecting diagnostics, and the pre-warm flag), both recovered, and my hypotheses about this system have been wrong five times.

   The experiment to run

   1. Disposable mesh with a real clustering provider and two portal containers; compile a NodeType with cross-type shared= sources; read the phase split (core Compile: record the phase split in the activity log — stop guessing where 45s goes #685 prints it) — discovery should jump from ~0 ms to tens of seconds if this is right.
   2. If it reproduces, the fix is in the read/routing path for a node owned by a remote silo, not in the compile path and not in pre-warming.
   3. As a control, the same on one silo.

   If it does NOT reproduce, this hypothesis is dead too and the remaining difference is scale (node count, ~90 schemas in the cross-schema search) rather than topology.
3. rbuergi commented on Jul 28, 2026

   

   rbuergi

   on Jul 28, 2026

   ContributorAuthor

   More actions

   Attempted the two-silo repro locally — blocked on harness setup, not on the hypothesis

   Tried to reproduce the stall on the disposable mesh with two silos (the variable my earlier 0 ms measurement never controlled for). Zero production risk, and it got far enough to be worth handing over rather than repeating:

   What worked

   • Features__Orleans__Clustering: "AdoNet" is the multi-silo provider (Localhost = one in-process silo — Doc/Architecture/FeatureFlags), and the disposable mesh already runs Postgres, so no extra infrastructure is needed.
   • Overlay file + docker compose --scale portal=2 is the right shape.

   What blocked it

   1. docker-compose.yml pins the portal to host port 8323, so two replicas collide (Bind for 0.0.0.0:8323 failed). Fixed with a port range: ports: !override ["8323-8324:8080"].
   2. Compose interpolation needs both MW_PLUGINS_REPO and MW_EDUCATION_REPO even for logs/ps; up.sh sets them, direct docker compose calls do not.
   3. With that resolved, the migration container never exits under AdoNet clustering (still Up after 10 minutes; it normally completes and lets the portal start via service_completed_successfully). The portals therefore never came up. I did not chase this further.

   So the harness is single-silo by construction and needs a small amount of work — most likely Orleans AdoNet membership tables that the migration image does not create — before the experiment can run. That is a contained task for someone fresh, not a blocker on the idea.

   Why the experiment is still the right next step: on one silo every hub is local and a read cannot miss, which is exactly the 0 ms result. On two, a read for a node owned by the other silo must be routed there, and the failing production read says NO LOCAL HUB … it never activated here (or is owned by another silo). If discovery jumps from ~0 ms to tens of seconds when the second silo joins, the defect is in the read path for remotely-owned nodes — not the compile path (#685 instrumentation proves that part is 0 ms), and not something pre-warming can absorb (that was tried on memex and degraded 7 of 16 roots).

   Everything torn down; no stray containers or files.
4. rbuergi commented on Jul 28, 2026

   

   rbuergi

   on Jul 28, 2026

   ContributorAuthor

   More actions

   Two more hypotheses dead, and the strongest lead yet — measured on memex itself

   1. Silo count is NOT the cause

   Built the two-silo repro (the blocker was that Orleans membership lives in a separate orleans database and OrleansClusteringSetup skips itself when ConnectionStrings:orleans is unset — the migration wasn't hanging, it was no-opping). With both silos Active in one cluster and a NodeType using cross-type shared= sources:

   ⏱ NodeType definition resolved in 0ms (ok); source-freshness scan 0ms.
   ⏱ Source discovery took 0ms (synced query) — everything below this line is Roslyn.
   TOTAL: 165ms
   

   Same as one silo. Topology is not the difference.

   2. Scale/query cost is NOT the cause either

   Timed the exact discovery queries a Store/Coupon compile issues, against memex, read-only:

   query	time	count
   namespace:Store/Coupon/Source scope:subtree nodeType:Code	0.26 s	1
   path:Store/Plugin/Source nodeType:Code	0.25 s	0
   namespace:Store/Plugin/Source scope:subtree nodeType:Code	0.28 s	16
   namespace:Store/Order/Source scope:subtree nodeType:Code	0.20 s	4

   The data is reachable in a quarter of a second, with the right counts, on the production mesh. ~90 schemas and thousands of nodes are not the problem.

   So the remaining difference is the MECHANISM

   path	on memex
   discovery queries via the search/read path	~0.25 s
   the same discovery inside a compile	45.20 s

   Compile discovery goes through the cached synced query (NodeSources.GetSources → workspace.GetQuery(id, queries)), not the direct read path that just answered in 0.25 s. Everything now points there, and nowhere else:

   • the compile path itself is exonerated (0 ms on a fresh mesh, 1 silo and 2)
   • the queries are exonerated (0.25 s on memex)
   • the data is exonerated (correct counts returned)

   Why my earlier attempt at exactly this failed

   PR #682 tried to race the cached synced query against a direct IMeshService.Query probe and never fired once in production. Given the above, that is now the most interesting fact in this issue: either the probe never ran (an Amb/gating mistake in that PR — it also required a non-empty result and a 3 s subscription delay), or IMeshService.Query shares whatever the cached path is waiting on, while the MCP search route does not.

   Next step: instrument NodeSources.GetSources/SnapshotSources to log subscribe→first-emission latency and which route answered, then compare the three routes on the same mesh in one run. That is a logging-only change, and it would finally separate "the cache is slow to deliver" from "the query is slow" — the two have been conflated in every attempt so far, including mine.
5. rbuergi

   added 4 commits that reference this issue on Jul 29, 2026

   Compile discovery: read sources directly instead of through the live …

   ...

   e004eed

   Flakes: give hub tests a budget the CI fixture can actually meet

   ...

   8876276

   Compile discovery: read sources directly instead of through the live …

   ...

   de86b03

   Flakes: give hub tests a budget the CI fixture can actually meet (#688)

   ...

   bc9906b
6. rbuergi commented on Jul 29, 2026

   

   rbuergi

   on Jul 29, 2026

   ContributorAuthor

   More actions

   Follow-up with measurements from unbreaking main after #690 landed.

   #690 fixed the production stall, but its ordering regressed every healthy mesh, because Concat is sequential rather than a fallback: the synced query is not even subscribed until the direct probe completes. So every compile paid the probe's full latency up front — and the probe cannot answer faster than SourceProbeQuietWindow (1s), since each leg must watch its chunked Initial go quiet before it may emit. That is a ~1s floor per compile the previous code never paid (the probe was DelaySubscription'd and on a healthy mesh never ran).

   Measured, one box, CompileLeafStabilityTest:

   build	duration
   before #690 (cached query primary)	4 s
   #690 as merged (probe → cached)	52 s
   Concat → Merge (true race)	4 s

   Full MeshWeaver.Hosting.Monolith.Test: 7m50s → 3m13s (CI's cap is 6m — this is why main went exit=124 on every run from de86b033a onward). Fix is in #708.

   The part worth keeping open this issue for. That 1s floor cost minutes, not seconds, because it lands on far more calls than actual compiles:

   MeshNodeCompilationService.cs:326 → DiscoverSourceMaxLastModified → SnapshotSources, and the disk cache is keyed by effectiveLastModified — which that scan produces. So source discovery runs BEFORE the cache can be consulted, and a cache HIT pays it in full. The cache saves Roslyn; it never saves discovery. In any workload that touches the same NodeTypes repeatedly, the cache-hit path is the common case.

   Concrete optimisation available: DiscoverSourceMaxLastModified only needs MAX(LastModified), but SnapshotSources fetches every source node's full content, accumulates it into a path→node map, waits out the 1s quiet window, and then discards the bodies on a cache hit. A cheap max-last-modified aggregate per query would make cache hits near-free and put the compile path well below the pre-#690 baseline. Not attempted here — it is a design change to code measured in production, and out of scope for unbreaking main.

   One thing explicitly NOT done: shrinking SourceProbeQuietWindow to 50ms, which also takes 52s → 7s. That window exists so a chunked Initial can settle, and the code's own comment warns a partial source set "compiles WRONG (missing files → phantom errors)".
7. rbuergi commented on Aug 8, 2026

   

   rbuergi

   on Aug 8, 2026

   ContributorAuthor

   More actions

   The remaining half, counted rather than reasoned about — PR #969

   Picking up the last comment's "Concrete optimisation available … Not attempted here". First, to be
   explicit about what is already closed: the 45.20 s headline is not what this addresses. That was
   the cached synced query missing its Initial and idling one SyncStreamOptions.HeartbeatInterval
   (45 s, to within 200 ms), fixed by #690 + #708, both on main. The title's cold-hub-activation
   hypothesis was disproved earlier in this thread (two silos = the same 0 ms as one; the queries answer
   in ~0.25 s on memex).

   What I measured

   Instrumented the source-set materializations and counted them on CompileActivityLogTest, instead of
   inferring them:

   per successful compile	source-set races that hit the mesh	live IMeshService.Query discovery reads
   before	3	5–6
   after (#969)	1	2 (= N, the expanded query count)

   The three:

   stage	what it did with the set
   DiscoverSourceMaxLastModified	fold MAX(LastModified) for the disk-cache key, then discard the bodies
   CompileCore	the actual compile inputs
   DiscoverSourceVersionSnapshot	fold path → LastModified.Ticks into CompiledSources

   Each an independent RaceSourceSnapshot over a live collection, each issuing the full expanded
   query set. N is 2 in that test; the memex NodeType shapes in this issue expand to 4–9
   cross-partition queries, so 12–27 reads where 4–9 do. Each read is ~0 ms on a fresh mesh — which is
   precisely why the fresh-mesh control in this issue could never have shown it.

   Raw before/after, same three tests, per NodeType path:

   BEFORE   snapshot-sources ×3   direct-query ×5   type/LogStory
            snapshot-sources ×3   direct-query ×6   type/SnapStory
            snapshot-sources ×2   direct-query ×5   type/LogBroken   (failure path)
   
   AFTER    1 race (override=False) + 2 short-circuited (override=True), direct-query ×2, all three
   

   The fix

   Take the snapshot once in GetAssemblyLocationWithLog and thread it — into the cache-key fold,
   into CompileCore as its sourcesOverride, and out on a new CompileAttempt.Sources for the
   version-snapshot / failure-diagnostics stages. RaceSourceSnapshot is untouched: #612's
   empty-by-consensus rule and #690/#708's Merge semantics are unchanged. One race instead of three,
   not a different race.

   It is also a correctness fix. Three independent observations of a live collection can disagree, so
   the cache key could be folded from set A while set B compiled and set C was recorded as
   CompiledSources — the very set the recompile-needed check compares against.

   Not done, and why

   The other half of the suggestion — a content-free MAX(LastModified) aggregate so cache hits are
   near-free — needs a second select:-projected query shape. That adds a round trip on the cache-MISS
   path and breaks the invariant NodeSources documents at length (compile and IsDirty watcher share
   ONE GetQuery cache id, so "what the compile sees" === "what the watcher computes IsDirty
   against") — the bug class CodeEditRecompileTest exists to catch. NodeSources also carries an
   explicit NO select: — deliberately warning that omitting content makes the adapter emit
   NULL::jsonb AS content and the type compiles against empty sources with no error anywhere.

   Not verified

   Nothing was run against memex — this thread already records that triggering compiles there put 6 of
   16 roots onto the "did not settle" overlay. So the ~0.25 s-per-read figure that converts the
   read-count win into wall clock is this issue's own measurement, not a fresh one. Locally the mesh
   is in-memory, so the wall-clock saving is milliseconds; the win is the read count, which is what
   scales with the mesh.
8. rbuergi commented on Aug 9, 2026

   

   rbuergi

   on Aug 9, 2026

   ContributorAuthor

   More actions

   Closing — but the reason is not the one the title implies, so it is worth recording precisely.

   The headline 45 s was already fixed before this PR

   The 45.20 s was not cold-hub cost. It was a cached synced query missing its Initial and idling one SyncStreamOptions.HeartbeatInterval (that constant is 45 s — src/MeshWeaver.Data/Serialization/SyncStreamOptions.cs:18, which is what makes the number suspiciously round). #690 + #708 fixed that, and both are on main.

   The title's hypothesis — that this is cold hub — was already dead in this thread: two silos measured the same 0 ms as one, and the discovery queries answer in ~0.25 s on memex. Claiming PR #969 fixed the 45 s would have been a fabricated win.

   What #969 actually fixed

   The part this thread explicitly left open ("Concrete optimisation available … Not attempted here"): discovery was paid more than once per compile. Counted on CompileActivityLogTest rather than argued:

   per successful compile	discovery races hitting the mesh	live IMeshService.Query reads
   before	3	5–6
   after	1	2 (= N, the expanded query count)

   The three were DiscoverSourceMaxLastModified (folds MAX(LastModified) for the cache key, then discards the bodies), CompileCore (the real inputs), and DiscoverSourceVersionSnapshot (records CompiledSources) — each an independent race over a live collection. N is 2 in that test; the memex NodeType shapes here expand to 4–9 cross-partition queries.

   It is also a correctness fix, not only a cost one: three independent observations of a live collection can disagree, so the cache key could be folded from set A while set B compiled and set C was recorded as CompiledSources — the very set the recompile-needed check compares against.

   Honest limits on the claim

   • Nothing was measured against memex. The ~0.25 s-per-read figure that would convert read-count into wall clock is this issue's measurement, not the PR's. The win it can stand behind is the read count — which is the thing that scales with the mesh.
   • The cache-hit path's 2 → 1 is derived from code structure, not separately measured.
   • The thread's other suggestion — a content-free MAX(LastModified) aggregate — was deliberately not done: it needs a second select:-projected query, adding a round trip on the cache-miss path and breaking the invariant that compile and the IsDirty watcher share one GetQuery cache id (the bug class CodeEditRecompileTest exists to catch). That one genuinely is riskier than the win.

   Nothing here explains #618 or #890; both sit downstream of Roslyn/assembly-load, and this change touches only source discovery.
9. rbuergi

   closed this as completedon Aug 9, 2026