Compile: record the phase split in the activity log — stop guessing where 45s goes by rbuergi · Pull Request #685 · Systemorph/MeshWeaver

rbuergi · 2026-07-28T02:58:59Z

Why this exists

Three fixes were attempted for the 2026-07-27 outage tonight. All three were guesses at a mechanism, because nothing measures the compile's internals. The activity log shows 45.20 s between "Invoking compiler…" and the source queries resolving, against 2.83 s of Roslyn — but why was reconstructable only by subtracting microsecond timestamps and then inventing a story to fit.

Every story was wrong:

guess	disproved by
the cached synced query stalls (#682)	the uncached probe never fired in production — zero log lines
a lost `Initial` waits for the 45 s heartbeat (#684)	starting the heartbeat early changed nothing: 48 s before, 57 s after
`15 s GetMeshNode + 30 s SnapshotSources = 45 s`	Loki shows those 15 s stalls on `LocalSyncDemo/_Sync/party-1` (82×), never on the compile path

What it adds

Three clocks, written into the compile's own ActivityLog, so a single get @{Type}/_Activity/compile-… shows the split with no log correlation and no arithmetic:

⏱ NodeType definition resolved in {ms}ms (ok | NULL — the read stalled or the node is absent);
  source-freshness scan {ms}ms.
⏱ Source discovery took {ms}ms (synced query | caller-supplied override) —
  everything below this line is Roslyn.

The null-definition case is called out explicitly because that read is a bounded 15 s EmitNull: on a stall it yields null and the compile proceeds against a null definition — which the surrounding comment already admits is "a silently wrong compile". If that is what's happening on memex, this line says so outright.

Scope

Logging only, no behaviour change. 647/647 Graph tests pass.

What to do with it

Deploy, run one compile of Store/Coupon (the type measured all night — 23 Code nodes across four types via shared=), and read the activity node. The 45 s is in exactly one of three places, and this says which. Then fix that, with evidence instead of a fourth story.

🤖 Generated with Claude Code

…here 45s goes Three fixes were attempted for the 2026-07-27 outage and all three were guesses at a mechanism, because nothing measures the compile's internals. The activity log showed 45.20s between "Invoking compiler…" and the source queries resolving, against 2.83s of Roslyn, but WHY was reconstructable only by subtracting microsecond timestamps and then inventing a story to fit. Each story was wrong: - "the cached synced query stalls" → the uncached probe never fired (#682) - "a lost Initial waits for the 45s heartbeat" → starting the heartbeat early changed nothing measurable in production (#684: 48s before, 57s after) - "15s GetMeshNode + 30s SnapshotSources = 45s" → Loki shows those 15s stalls happening on LocalSyncDemo/_Sync/party-1, never on the compile path So measure instead. Three clocks, written into the compile's OWN ActivityLog, so one `get @{Type}/_Activity/compile-…` shows the split with no log correlation: ⏱ NodeType definition resolved in {ms}ms (ok | NULL — the read stalled …); source-freshness scan {ms}ms. ⏱ Source discovery took {ms}ms (synced query | caller-supplied override) — everything below this line is Roslyn. The null-definition case is called out explicitly because that read is a bounded 15s EmitNull: on a stall it yields null and the compile proceeds against a null definition, which the code already documents as "a silently wrong compile". Logging only — no behaviour change. 647/647 Graph tests pass. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Copilot

Pull request overview

Adds phase-level timing instrumentation to MeshNodeCompilationService so compile activities record where time is spent (NodeType definition resolution, source freshness scan, and source discovery), making 45s+ stalls diagnosable directly from the per-compile ActivityLog.

Changes:

Record definition-resolution and source-freshness timings into the compile ActivityLog.
Record source-discovery timing (synced query vs caller override) into the compile ActivityLog.

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

+                var discoveryLog = AppendInfo(log,
+                    $"⏱ Source discovery took {discoveryClock.ElapsedMilliseconds}ms "
+                    + $"({(sourcesOverride is not null ? "caller-supplied override" : "synced query")}) — "
+                    + "everything below this line is Roslyn.");


github-actions · 2026-07-28T03:17:50Z