Which Kind of Silence

A portal's log stops. The page in front of the user says "Subscribing to …". Ninety seconds later a test gives up, or a person reloads.

Error Propagation & Wedges says what to do about a wedge, and the whole of that page assumes the thing you are looking at is one. This page is about the step before: a quiet log has four causes, they have four different owners, and for a long time they produced the same bytes — none.

The heartbeat

ProcessLiveness publishes one line, unconditionally, every Diagnostics:LivenessHeartbeatSeconds (default 10 s; 0 switches it off and says so):

[LIVENESS] tick=7 gap=10.01s/10.00s gen0=453(+3) gen1=422(+1) gen2=21(+0)
           gcPause=20.00s(+0.00s) heap=5.81GiB serverGC=False
           poolThreads=55 poolPending=0 poolCompleted=1004321(+4321)

Read a quiet window against it:

Two design choices carry the whole thing, and both are the opposite of what a first draft does.

The line is unconditional. Every other stall instrument in the platform — Orleans' watchdog, the disposal stall verdict, the pending-callback report — fires when something is noticed, and every one of them reports on resume. A stop that outlives the process therefore prints nothing, and that is precisely the window a wedge investigation is reading. An instrument that prints only when it is unhappy makes "nothing happened" and "I was not running" the same bytes — the ambiguity the /health census tag removes one layer up, restated at the log. The cost is one ~200-byte line per process per period (≈1.7 MB per pod per day at the default), stated rather than minimised.

The tick runs on a thread of its own. A tick scheduled on the ThreadPool — a Timer, Observable.Interval, a BackgroundService loop — is silenced by the pool starvation it exists to name, so rows 2 and 3 of that table would collapse into one. The precedent is IoPool.StartCanceller, which refuses the pool for the same reason: the work you are trying to observe may be holding every slot. And a tick that throws reports and continues — a heartbeat that dies on one bad read goes silent forever, and its silence then reads as row 3. An instrument that can manufacture its own verdict is not an instrument.

The case this was built from (#4234)

MeshWeaver.Education's install e2e opened a freshly-installed exercise page and waited 90 s for its workbench. One page never rendered. Its accessibility snapshot resolved every breadcrumb and held the wedge string this platform documents by name:

- text: Subscribing to …/ThinkInStreams/06-DataBinding/Exercise/MergePatch…
- progressbar
- text: Reconnecting… The server was updated. Reloading the page…

The portal's last log line of the entire run was 08:29:13.917Z. The container never restarted, no core dump was written, and docker stats sampled the process at 1–7 % CPU for the whole window. It was filed as a layout subscription that wedged while the portal sat idle.

Both readings that supported that were wrong, and the run's own artifacts said so.

🚨 The CPU samples exclude nothing — the run carries its own positive control. Five minutes earlier the same process took a stall Orleans did report on resume: Platform stalled for 00:00:13.70. Total GC Pause duration during that period: 00:00:13.64. The docker stats sample that lands inside that confirmed stop-the-world pause reads 2.14 %. So on this host a measured 13.64 s GC pause and an idle process are indistinguishable by CPU. "Single-digit CPU, therefore not GC" is falsified by the same artifact that proposed it.

🚨 The failing unit was not a subscription. The run's Playwright trace records every request the browser made. At 08:29:14.09 — 0.17 s after the portal's last log line — six ordinary static-file GETs for _content/…/*.razor.js were issued and never completed (status = -1), and at 08:29:46.17 the Blazor reconnect's POST /_blazor/negotiate did the same. Static files are served by Kestrel's static-file middleware and touch no hub, no stream and no layout area. The whole HTTP server stopped answering; the "Subscribing to…" text was simply what the page happened to be showing when the process froze underneath it.

The remaining question — a suspended process versus a merely-idle one — is the row-1-versus-row-3 question above, and nothing inside the process could answer it. That is what the heartbeat is for.

Two lessons that generalise past this incident

A stall instrument that reports on resume cannot see the stop that kills the process. Orleans' watchdog reported the 13.7 s pause and reported nothing about the 90 s one, and both behaviours are correct for what it is. Any instrument of that shape has the same blind spot; the fix is never to lower its threshold.

An external CPU sample is not a liveness signal. It was read as one here, and it is read as one often. Measure liveness from inside the process, where "I am still executing" is a thing that can be said.

A heap step names its allocator: the [HEAPSTEP] line

The heartbeat's heap= field (GC.GetTotalMemory(false)) is what showed MeshWeaver#5555's shape. The public instance's replicas took multi-GiB live-heap steps: +2 to +10 GiB inside one 100 s sample, on several replicas within seconds of each other (01:00:02Z and 01:00:11Z; 03:31:48Z and 03:31:56Z on 2026-09-24). The heap stayed up through gen-2 collections, and one replica died of OutOfMemoryException. The field says how much was added. It cannot say what was added, and no reading could be taken at the moment of a step:

• a --type Heap dump of a replica this size freezes it for about 106 s, which is past the liveness budget, so it restarts the container (The Portal Heap Is Hubs);
• the steps are unpredictable, so nobody is at the pod with a tool when one lands.

So the heartbeat now carries the reading itself. AllocationByTypeSampler is an in-process EventListener on the runtime's GC keyword. The runtime already raises one GCAllocationTick event per ~100 KB allocated, and each event names the allocated type. The sampler sums those events per type between two ticks. When a tick's heap has grown by ProcessLiveness.HeapStepThresholdBytes (512 MiB) or more since the previous tick, a Warning follows the [LIVENESS] line:

[HEAPSTEP] tick=41 heap=2.00GiB→8.00GiB (+6.00GiB) in 10.00s; sampled allocation in the window
6.00GiB, heaviest types: System.Byte[]=5.00GiB (83%) System.String=1.00GiB (17%). Allocated, not
retained: the leading type is the candidate for what the step holds.

How to read it:

• It names what was allocated, not what is retained. A step is memory that was allocated AND is still reachable. A type that dominates a window in which the heap grew by gigabytes is the leading candidate. A dump of a quiet replica confirms what roots it.
• It is a sample. Types of a few hundred KB are noise. A type of several GiB is not.
• The line is conditional, and the [LIVENESS] line is not. An absent [LIVENESS] line is a reading on its own. An absent [HEAPSTEP] line only means the heap did not step in that tick, and heap= already says so.
• An empty type list is stated, never implied, and the two reasons for one are told apart. If the sampler could not start, a step still prints and says "the allocation sampler is NOT running in this process". If it is running and sampled nothing in that tick, the line says "the sampler is running but sampled NO allocation in this window". It never prints an empty list that would read as "nothing was allocated".
• A sample is never lost to a drain. The window is one immutable map, and both sides replace it by compare-and-swap: a record folds its sample in with ImmutableInterlocked.AddOrUpdate, and a drain takes the map with Interlocked.Exchange. A record that races a drain therefore retries against the fresh map instead of adding to one nobody reads again.
• Find it with the same Logs action as the heartbeat: query: "HEAPSTEP\\] tick=", per pod.

What the first readings named

The first live readings came from image 3.0.0-ci.9408 on both portals, 2026-09-26 between 10:00Z and 18:15Z. Logs actions Ops/Actions/logs-memexcloud-20260926-heapstep-5555 and …/logs-memex-20260926-heapstep-5555 read 43 and 88 lines, none cut.

• Every step past warm-up has the same allocation mix. System.String is 53–56 % of the sampled bytes, System.Byte[] 25–31 %, and System.Text.Json.JsonDocument 2–4 %. The mix is the same on the control instance and on the public instance, and across pods. A window allocated 4–7 GiB in 10 s. Only the first ticks after boot differ, when assembly loading (CoffHeader) and serializer set-up are in the mix.
• The steps are churn, not retention. With server GC, a gen-0 budget is gigabytes, so GC.GetTotalMemory(false) includes garbage until the next collection. On memex-portal-deployment-6c7669df84-nbrdx, tick 314 read heap=4.44GiB. Tick 315 ran two gen-0, one gen-1 and one gen-2 collection and read 3.03GiB. At the 512 MiB threshold, a [HEAPSTEP] line here marks an allocation burst. It does not by itself mark a leak.
• String ≈ 2 × Byte[] plus a JsonDocument suggests a JSON round trip, but does not identify its caller or prove duplication: UTF-8 input and a correctly materialized UTF-16 leaf can also contribute that mix. ObjectPolymorphicConverter.ReadObject did duplicate the whole value for every object-typed value. It copied the value into a JsonDocument, took GetRawText() as a string, and deserialized that string again. Each nested object member re-enters the converter, so this happened once per nesting level. PolymorphicReadAllocationTest measures one read of a value nested 8 levels deep, with a 400,000-byte leaf string: 4,006,624 bytes allocated before the fix, 402,024 after. The leaf itself is the floor.
• The fix. When $type is the first property, names a registered type, and there is no reference metadata, the converter now deserializes straight from the reader, with no document and no string. Every other shape takes the general path as before, and that path now deserializes from UTF-8 instead of a string.
• Not yet established: whether this converter is the dominant caller in production. The sampler names types, not call sites. A high String share after the repair keeps the allocation investigation open, but cannot distinguish another whole-JSON copy from strings that content needs to materialize.

A query read still copied the whole value

On 2026-09-27, Ops/Actions/verify-5555-memexcloud-20260927-heapstep read and landed 50 lines from the three 3.0.0-ci.9443 replicas, with no failures or truncation. Nine windows still attributed more than 50 percent of sampled allocation to strings. That image contains the converter repair. These are allocated bytes, not retained roots, and they still do not attribute a caller.

An independent code-path control found another full-value copy: MeshNodeStreamCache.DeserializeContent, which re-types every emitted query node, called JsonElement.GetRawText() or JsonObject.ToJsonString() before deserialization. QueryContentAllocationTest drives that production method with real hub serializer options and a registered content type. After warm-up, a 512,000-byte leaf costs 1,024,616 allocated bytes through either input shape before the repair. Reading the JSON representation directly reduces the JsonElement case to 512,504 and the JsonObject case to 512,696, while preserving the typed leaf. Raw diagnostic text is now formed only when re-typing fails; registry recovery and the degradation warning's exception still run as before.

Truncating after GetRawText() or ToJsonString() also allocated the whole failed payload. BoundedJsonDiagnostic (since removed — see below) read a bounded UTF-8 span from a JsonElement, or visited a JsonNode until its character budget was reached. String escaping received only the remaining prefix, and custom value converters were not invoked for diagnostics. The same formatter supplied stream and query warnings. A 256,000-character escaped leaf used 1,026,168 allocated bytes with the old serialize-then-truncate path; the three JSON shapes now stay below the 64,000-byte test bound. Small JSON, UTF-8 cuts, and disposed-document diagnostics have separate controls.

That formatter has since been replaced, for a reason that has nothing to do with memory: the degradation warnings are Warning-level and ship to the central log store, which row-level security does not reach, so a bounded prefix of the stored value still copied a node's content to every reader of the logs. The warnings now carry the content's shape — the $type (or no $type), the JSON kind, the top-level property names (at most 32, each cut and JSON-escaped) and the byte length — and no value. ContentShapes.Describe (MeshWeaver.Data.Contract) is the one implementation every site uses, and it keeps the allocation property above: a JsonElement is measured from its raw UTF-8 span; a JsonNode is sized over its top level only, never serialized and never descended into (descending would materialise a parsed tree's lazy containers), so no converter runs and no payload is materialised — the size is printed ~ when complete and ≥ when a nested container or the entry budget left it a lower bound. Only the displayed names are decoded, each cut before decoding; the discriminator is matched on raw bytes. The marker's MeshNodeContentDegradedException.Shape carries the same text; its old RawJson property survives only as an [Obsolete] forwarder that the platform's own sites leave null. DegradedContentLogsShapeNotValuesTest drives the production seams with a value-bearing payload and asserts the value is absent from the formatted line, the marker's Message and its ToString(), while the $type and keys are present.

This establishes and removes a per-query whole-JSON string copy. It does not establish its share of the production allocation windows or explain retained memory. After the supported roll, exercise query content re-typing on the portal and repeat the heap readings before deciding whether #5555 can be closed.

HeapStepNamesItsAllocatorTest pins the rule with pure tests. It also has a live test: it allocates ~160 MiB of a marker type and requires the sampler to attribute at least 64 MiB of it to that type. That live test is the positive control. A sampler that received nothing would make every real line say "cannot name".

A stalled pool names its frame: the [POOLSTALL] line

The [LIVENESS] line can say that the pool starved — poolCompleted(+0) with poolPending above zero, on a tick whose gap is on time. It cannot say what held the workers. A stall like that leaves nothing behind: the process does not crash, so no dump is written, and no governed action can read the stacks of a live pod. Every recurrence was therefore re-triaged from the same symptom (#5388).

So the heartbeat now acts on that reading. On the first tick in which the pool finished no work item while work was queued at both the previous tick and this one, it captures every ThreadPool worker's stack, once, and logs them grouped by their innermost 12 frames, the largest group first:

[POOLSTALL] tick=1099: the ThreadPool completed no work item in the last 10.12s with 20357 queued over 69 thread(s). 69 worker stack(s) in 3 distinct shape(s), largest first (innermost 12 frames each):
  ×61:
     at <the frame the pool is held in>
     …

• How the stacks are read. The heartbeat has its own thread, which the stall cannot hold, and it hands the capture to a second dedicated thread so a slow or hung capture can never silence the [LIVENESS] line; one capture is in flight at a time. The capture writes one Normal minidump of its own process (thread stacks and module data, no heap) and reads it back with ClrMD, then deletes the file. This is the same reader, with the same DAC pin, that the silo stop uses for leaves that outlive its join (#7277): BlockedThreadStacks.CaptureThreadPoolWorkers, registered as IThreadPoolWorkerStacks by AddThreadPoolWorkerStacks() in every Orleans silo.
• Cost. The dump suspends the process for about a second. It is taken at most once every 30 minutes (ThreadPoolStall.CaptureCooldown), and only after a whole period in which the pool served nothing.
• When it cannot read stacks. The line still prints and says why: no reader registered in this host, the capture failed (with the exception), or the dump held no pool worker.
• A missing [POOLSTALL] line does NOT rule out starvation. Three cases print none for a real stall: a capture already taken in the last 30 minutes (the cooldown), a capture still in flight, and a capture that hangs and never logs. Decide whether the pool made progress from the [LIVENESS] counters (poolCompleted(+0) with poolPending above zero, on consecutive ticks), never from the absence of this line.
• Tests. ThreadPoolWorkerStacksTest parks real pool workers in a known method, captures a real dump, and requires exactly those workers in that method, rendered as one group naming it. Its negative control takes the same capture with nothing parked and must not find the method. ThreadPoolStallTest pins the decision (stalled, idle, busy, first tick, cooldown) and the line's grouping and ordering over controlled inputs.

The stall that made this necessary

memex-cloud, pod 6997ff97bc-5q8t2, image 3.1.12401, 2026-11-02. Read through governed Logs actions on the control instance (Ops/Actions/t1102-5388-*):

Orleans logged Thread Pool execution stalled for 21.95s (08:58:56) and 24.27s (08:59:21), and a SiloHealthMonitor timer that fired 35.7 s late. The pod then drained and exited cleanly (exit 0, no dump on the volume).

What these readings establish:

• It was not a machine pause or a crash dump. Every heartbeat tick was on time. The 10-23 and 10-30 reopens of #5388 were the opposite case: createdump freezing a dying process.
• It was not GC. GC took 6–11 % of each tick.
• It was real starvation. 69 workers finished nothing for whole periods. The runtime added no thread in about 90 s.
• It happened during a NodeType compile and release wave. At 08:59:21 the compile lane was full, with six of six slots running and four queued, and its longest wait so far was 235 s. Sampled allocation was dominated by Roslyn symbol types.

What they do not establish is the frame the 69 workers were in. That is what the [POOLSTALL] line exists to capture at the next occurrence.

Where this sits

Error Propagation & Wedges — what must always happen once you know it is a wedge. Action-Block Wedge Prevention — why a single thread saturates. Reading a Disposal Stall Verdict — the same "what does this field actually measure" discipline applied to the disposal snapshot, including three fields that were read as evidence while measuring nothing. Debugging Message Flow — how to trace a live hang once the process is known to be alive.