feat(liveness): a heap step names what was allocated in it — [HEAPSTEP] (Refs #5555) - #5665
Conversation
…], Refs #5555) memex-cloud replicas take multi-GiB live-heap steps (+2..+10 GiB inside one 100 s [LIVENESS] sample, several replicas within seconds) and no reading could name the allocator: a Heap dump of a replica this size restarts it, and the steps are unpredictable. AllocationByTypeSampler listens in-process to the runtime's own sampled GCAllocationTick events (one per ~100 KB, carrying the type) and sums them per type between heartbeat ticks. A tick whose heap grew by >= 512 MiB now logs a [HEAPSTEP] Warning naming the heaviest types allocated in that window; a host whose sampler did not start says it cannot name them. HeapStepNamesItsAllocatorTest: pure line tests plus a live test that allocates ~160 MiB of a marker type. Negative control: the listener enabled at Informational (AllocationTick is Verbose) -> the live test is red. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
There was a problem hiding this comment.
Copilot review overview
🟡 Changes recommended
Unresolved moderate findings affect attribution correctness, initialization safety, threshold behavior, and heartbeat reliability.
Get a fresh assessment by requesting another Copilot review.
Review effort: Lite
Findings: 2
Open (3)
What changed in this PR
Adds in-process GC allocation sampling to annotate significant heap-growth intervals with [HEAPSTEP] warnings, plus tests and documentation.
Changes:
- Samples allocation events by type.
- Integrates heap-step diagnostics into liveness heartbeats.
- Adds formatter/sampler tests and operational documentation.
| File | Summary |
|---|---|
test/MeshWeaver.Hosting.Test/HeapStepNamesItsAllocatorTest.cs |
Adds pure and live sampler/formatting tests. |
src/MeshWeaver.Hosting/ProcessLivenessHeartbeatService.cs |
Integrates sampler lifecycle and warning logging. Moderate: sampler failures may suppress [LIVENESS] (1 vote). Nit: missing integration coverage (1 vote). |
src/MeshWeaver.Hosting/ProcessLiveness.cs |
Adds heap-step detection and formatting. Moderate: per-tick threshold may miss distributed growth (1 vote). Nit: empty windows conflate unavailable samplers with no events (4 votes). |
src/MeshWeaver.Hosting/AllocationByTypeSampler.cs |
Adds runtime allocation sampling. Moderate: Record/Drain can discard racing samples (2 votes). Moderate: construction may receive callbacks before state initialization (2 votes). |
src/MeshWeaver.Documentation/Data/Architecture/WhichKindOfSilence.md |
Documents [HEAPSTEP] interpretation and log queries. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
| // Swapped whole by Drain. A sample racing the swap lands in either window, never nowhere that | ||
| // matters: at ~100 KB per sample one misplaced sample is noise against a multi-GiB step. | ||
| private ConcurrentDictionary<string, long> window = new(StringComparer.Ordinal); |
There was a problem hiding this comment.
Agreed, and fixed in 419e8bb.
The window is now one ImmutableDictionary, and both sides replace it by compare-and-swap:
Recordfolds each sample in withImmutableInterlocked.AddOrUpdate;Draintakes the map withInterlocked.Exchange.
A record that races a drain now fails its CAS and retries against the fresh map, so it can no longer add to a map nobody reads.
New test: ConcurrentRecordAndDrain_LoseNoSample runs 4 writers × 50,000 samples against a draining loop and requires every sample to land in exactly one drained window. Negative control: with the old swap of a mutable map restored, it goes red at 196,239 of 200,000.
| // Runs from the base constructor for sources that already exist, so it must not touch state | ||
| // the derived constructor would set; `window` is a field initializer, which C# runs first. | ||
| if (eventSource.Name == RuntimeProviderName) | ||
| EnableEvents(eventSource, EventLevel.Verbose, GcKeyword); |
There was a problem hiding this comment.
I checked the ordering here, and it is the other way round in C#. Instance field initializers run before the base-constructor call (C# spec §15.11.3, "Constructor execution": variable initializers execute before the base-class constructor invocation). So window is already assigned when EventListener's constructor calls OnEventSourceCreated, and an event delivered straight after EnableEvents finds a valid map.
(The version of this hazard that does exist is state assigned in the derived constructor body. This type has none.)
The live test builds the sampler and immediately allocates. It passes, which would not hold if early events hit an unassigned field. In 419e8bb I reworded the comment at that call so it says exactly this.
| return line.Append( | ||
| " — NO allocation was sampled in this window, so this line cannot name the allocator " | ||
| + "(the sampler is not running in this process).") | ||
| .ToString(); |
There was a problem hiding this comment.
Agreed, fixed in 419e8bb. DescribeHeapStep now takes AllocationWindow?, and the two cases print different sentences:
nullmeans the process has no sampler: "the allocation sampler is NOT running in this process";AllocationWindow.Emptymeans a running sampler saw nothing: "the sampler is running but sampled NO allocation in this window".
The heartbeat passes sampler?.Drain(), so the two cases stay separate. AStepWithoutSamples_SaysItCannotNameTheAllocator_AndWhy pins both.
…d "sampled nothing" are two sentences Review on #5665: - the window was a mutable map swapped by reference, so a Record that read the old map could add to it after Drain had taken it. Now one immutable map replaced by CAS on both sides (ImmutableInterlocked.AddOrUpdate / Interlocked.Exchange). ConcurrentRecordAndDrain_LoseNoSample: 4 writers x 50,000 samples against a draining loop; negative control (the old swap) -> 196,239 of 200,000. - DescribeHeapStep takes a null window for "no sampler in this process" and reports an empty one as "running but sampled nothing". Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
… cannot push it out of Top CI (queue run 36015948806, shard 5) read 199,960 of 200,000: the sampler is live, so other tests' real ~100 KB samples share its windows, and Drain reports only the TopTypes heaviest. 1-byte marker samples in a window fell below real types. The loss was in the test's arithmetic, not the sampler. Each marker sample now weighs 1 GiB, which heads every window it is in. Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
|
ℹ️ Merge-queue steward: no action — removed from the queue with reason |
…ion is present on every run The queue reds (199,960 of 200,000 at 419e8bb) came from the test's Top-N arithmetic under live runtime samples, not from a record/drain race. Deterministic now: a noise thread records 2 x TopTypes heavier types throughout. Controls, locally: - 1-byte markers under that noise: 186,946 of 200,000 (the CI shape) - 1 GiB markers, CAS sampler: exact - 1 GiB markers, the original mutable-map swap: 196,239 (the real race #5665 fixed) Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
|
ℹ️ Merge-queue steward: no action — removed from the queue with reason |
|
⛔ Merge-queue steward: left dequeued — a merge_group workflow other than the test suite failed on this pull request's queue branch; a gate failure is never a flake, so the steward re-queues nothing here — read the named workflow, and the test run too if it also failed.
|
meshweaver-cloud
Bot
added
the
queue-rejected
…t on Drain's Top-N summary Queue run 36016772968 (shard 5) read 187,818 of 200,000 at 419e8bb: the test summed the marker out of Drain().Top, and the live sampler also holds every other test's real ~100 KB samples, so a window that ranked the marker below TopTypes other types dropped it from the READING. The sampler lost nothing. dd1efea made that improbable by weighting the marker 1 GiB; this makes it structural: Drain() = Summarize(TakeWindow()), and the race test sums TakeWindow() — every type — so no ranking can hide a sample. A separate test pins the summary (heaviest first, TopTypes cap, total over every type). Controls, locally (Release): - CAS sampler: 200,000 of 200,000, 6/6 green - negative control, Record as a non-atomic read-SetItem-write: RED ("found 146175035") Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
|
The ejection cause is fixed on this branch (973af80). It is ready for the maintainer to re-queue with The queue red was dd1efea made that unlikely by weighting the marker at 1 GiB. 973af80 makes it impossible:
Controls, local Release build:
The PR run's first attempt went red on something unrelated: My push re-armed auto-merge through |
rbuergi
removed
the
queue-rejected
Refs #5555 · Refs #4847 · Refs #4883
Why this is an instrument and not a fix
The logs I could reach don't name the allocation behind #5555's multi-GiB live-heap steps (+2 to +10 GiB inside one 100 s
[LIVENESS]sample, landing on several replicas within seconds), so this PR contains no speculative fix. What it adds is the reading that would name it.The heartbeat's
heap=(GC.GetTotalMemory(false)) says how much was added, not what. A--type Heapdump of a replica this size freezes it for about 106 s and restarts the container (Doc/Architecture/PortalHeapIsHubs), and the steps are unpredictable, so a dump cannot be taken when a step lands.The change
AllocationByTypeSampler(Hosting) is an in-processEventListeneron the runtime'sGCkeyword atVerbose. The runtime already raises oneGCAllocationTickper ~100 KB allocated, and each carries the type. The sampler sums them per type between heartbeat ticks. It keeps only instance state, owned by the heartbeat thread.ProcessLiveness.DescribeHeapStepis pure. When a tick's heap grew by at leastHeapStepThresholdBytes(512 MiB), it produces a[HEAPSTEP]line naming the 8 heaviest types allocated in that window, with bytes and share. If the sampler could not start, the line says it cannot name the allocator. It never prints an empty list.ProcessLivenessHeartbeatServicedrains the sampler each tick and logs[HEAPSTEP]atWarningafter the unchanged[LIVENESS]line. The[LIVENESS]line itself is untouched. If the sampler cannot start, the heartbeat carries on exactly as before.Verification
HeapStepNamesItsAllocatorTest(Hosting.Test), 5/5:Informationalinstead ofVerbose(AllocationTick is a Verbose event) turns the live test red after 36 s, with the other 3 green. Restored → 4/4.ConcurrentRecordAndDrain_LoseNoSample(added after review) runs 4 writers × 50,000 samples against a draining loop. Negative control: the original swap of a mutable map lost samples, finishing at 196,239 of 200,000. With the CAS-on-both-sides map it is exact.HeapStepMarker[]), so the test matches on that suffix.ProcessLiveness*tests 14/14.MeshWeaver.Documentation.Test628/628.dotnet build -c Release -warnaserror, 0 warnings and 0 errors each: MeshWeaver.Hosting, MeshWeaver.Hosting.Test, MeshWeaver.Documentation.Test.Docs
Architecture/WhichKindOfSilencehas a new section, "A heap step names its allocator: the[HEAPSTEP]line". It covers what the line reads, why it is allocated-not-retained, why it is conditional while[LIVENESS]is not, and theLogsquery that finds it.After the roll
On memex-cloud, a
Logsaction withquery: "HEAPSTEP\\] tick="per pod. The first step on an image carrying this names its leading type, and that is the reading #5555 is waiting on. Nothing a per-node hub serves changes, so no recycle is needed.Pairs-with: none — additive only (three new public types and one new static method on
ProcessLiveness; nothing removed or renamed).Queue reds at
419e8bbc47, and what they wereTwo queue runs went red on
ConcurrentRecordAndDrain_LoseNoSampleat the earlier head419e8bbc47. One was in the group with #5661. The other was #5663's queue branch, which was built on top of #5665 while it sat ahead in the queue. The CI reading was 199,960 of 200,000.The cause was the test's arithmetic, not a record/drain race. The sampler is live, so other tests' real ~100 KB samples share its windows.
Drainreports only theTopTypesheaviest types, and 1-byte marker samples dropped out of the top 8. Fixed in6464781943(marker samples weigh 1 GiB) and made deterministic indd1efea654(the test runs its own noise thread of 2 ×TopTypesheavier types).Controls, measured locally on the final test:
IndexOutOfRangeException(red). This is the real race that the review fix removed. (Thedd1efea654commit message credits this control with "196,239". That figure was measured on the earlier 1-byte, no-noise version of the test, and this line is the correction.)Whole
MeshWeaver.Hosting.Testproject locally: 964/964.🤖 Generated with Claude Code