diff --git a/src/MeshWeaver.Documentation/Data/Architecture/WhichKindOfSilence.md b/src/MeshWeaver.Documentation/Data/Architecture/WhichKindOfSilence.md index 911774a346..b33dde3309 100644 --- a/src/MeshWeaver.Documentation/Data/Architecture/WhichKindOfSilence.md +++ b/src/MeshWeaver.Documentation/Data/Architecture/WhichKindOfSilence.md @@ -108,6 +108,56 @@ lower its threshold. 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. +memex-cloud 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](../PortalHeapIsHubs)); +- 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. + +`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". + ## Where this sits [Error Propagation & Wedges](../ErrorPropagationAndWedges) — what must always happen once you know it is diff --git a/src/MeshWeaver.Hosting/AllocationByTypeSampler.cs b/src/MeshWeaver.Hosting/AllocationByTypeSampler.cs new file mode 100644 index 0000000000..cd407d587f --- /dev/null +++ b/src/MeshWeaver.Hosting/AllocationByTypeSampler.cs @@ -0,0 +1,146 @@ +using System.Collections.Immutable; +using System.Diagnostics.Tracing; + +namespace MeshWeaver.Hosting; + +/// Sampled allocation volume of one type inside one heartbeat window. +/// The runtime's name for the allocated type, e.g. System.Byte[]. +/// The sampled bytes attributed to it (each sample stands for ~100 KB). +public sealed record TypeAllocation(string TypeName, long Bytes); + +/// +/// What the process allocated between two heartbeat ticks, by type, as the runtime sampled it. +/// +/// Every sampled byte in the window, across all types. +/// The heaviest types, largest first. +public sealed record AllocationWindow(long TotalBytes, ImmutableList Top) +{ + /// A window in which nothing was sampled — also what a host without the sampler reads. + public static readonly AllocationWindow Empty = new(0, ImmutableList.Empty); +} + +/// +/// Names WHAT a process allocated, by type, from the runtime's own sampled allocation events — +/// the reading the multi-GiB heap step (MeshWeaver#5555) was missing. +/// +/// 🚨 Why an in-process sampler and not a heap dump. The step is unpredictable (it has +/// landed at boot, at 01:00Z, at 03:31Z, on several replicas within seconds) and a dump is not free: +/// on a replica of this size dotnet-dump collect --type Heap froze the process for ~106 s, +/// past the liveness budget, and restarted the container (Doc/Architecture/PortalHeapIsHubs). +/// Nobody can be standing at the pod with a dump tool when a step lands, and the dump would kill the +/// replica it is reading. The runtime already samples its own allocations — one +/// GCAllocationTick event per ~100 KB allocated, carrying the type — so listening to +/// those costs one event per 100 KB and names the type in-band, at the step, in the log the +/// fleet already keeps. +/// +/// 🚨 Allocated is not retained. The window counts what was ALLOCATED. A heap step is +/// what was allocated AND is still reachable, so the report names candidates, heaviest first; a type +/// that dominates a window whose heap grew by gigabytes is the leading one, and a heap dump of a +/// quiet replica can then confirm what roots it. It is a sample, so small types are noise and a +/// multi-GiB type is not. +/// +/// Instance state only — the window is a field of this listener, which the heartbeat owns for +/// the life of the host. Nothing here is static except the constants. +/// +public sealed class AllocationByTypeSampler : EventListener +{ + /// The runtime's event source. + public const string RuntimeProviderName = "Microsoft-Windows-DotNETRuntime"; + + /// The GC keyword — the one GCAllocationTick is raised under. + private const EventKeywords GcKeyword = (EventKeywords)0x1; + + /// GCAllocationTick's event id (every version of it). + private const int AllocationTickEventId = 10; + + /// How many types a window reports. The step is one or two types, never forty. + public const int TopTypes = 8; + + // One immutable map, replaced by compare-and-swap on BOTH sides: Record folds a sample in with + // ImmutableInterlocked.AddOrUpdate, Drain takes the map with Interlocked.Exchange. A sample + // racing the drain therefore either lands in the map Drain took, or fails its CAS and is + // retried against the fresh one — it is never added to a map nobody will read again. + private ImmutableDictionary window = ImmutableDictionary.Create(StringComparer.Ordinal); + + /// + protected override void OnEventSourceCreated(EventSource eventSource) + { + // Runs from the base constructor for sources that already exist. That is safe here: the only + // state an event touches is `window`, and C# runs instance field initializers BEFORE the + // base constructor call, so it is assigned before this can be reached. + if (eventSource.Name == RuntimeProviderName) + EnableEvents(eventSource, EventLevel.Verbose, GcKeyword); + } + + /// + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + if (eventData.EventId != AllocationTickEventId || eventData.Payload is not { } payload + || eventData.PayloadNames is not { } names) + return; + + string? typeName = null; + long bytes = 0; + for (var i = 0; i < names.Count && i < payload.Count; i++) + { + switch (names[i]) + { + case "TypeName": + typeName = payload[i] as string; + break; + case "AllocationAmount64": + bytes = Convert.ToInt64(payload[i], System.Globalization.CultureInfo.InvariantCulture); + break; + case "AllocationAmount" when bytes == 0: + bytes = Convert.ToInt64(payload[i], System.Globalization.CultureInfo.InvariantCulture); + break; + } + } + + if (bytes <= 0) + return; + + Record(string.IsNullOrEmpty(typeName) ? "(unnamed)" : typeName, bytes); + } + + /// Adds one sample to the current window. + /// The allocated type. + /// The sampled bytes. + internal void Record(string typeName, long bytes) => + ImmutableInterlocked.AddOrUpdate(ref window, typeName, bytes, (_, sum) => sum + bytes); + + /// + /// The window since the previous drain, heaviest types first, and a fresh window started. + /// + /// What was sampled since the last call. + public AllocationWindow Drain() => Summarize(TakeWindow()); + + /// + /// Takes the WHOLE window since the previous take — every type, not only the heaviest — and + /// starts a fresh one. is this plus the Top- summary; + /// the record/drain race is a property of this take alone, so it is measured here, where no + /// ranking can hide a sample. + /// + /// Every type sampled since the last take, with its summed bytes. + internal ImmutableDictionary TakeWindow() => + Interlocked.Exchange(ref window, window.Clear()); + + private static AllocationWindow Summarize(ImmutableDictionary drained) + { + if (drained.IsEmpty) + return AllocationWindow.Empty; + + var total = 0L; + foreach (var entry in drained) + total += entry.Value; + + return new AllocationWindow( + total, + drained + .OrderByDescending(entry => entry.Value) + .ThenBy(entry => entry.Key, StringComparer.Ordinal) + .Take(TopTypes) + .Select(entry => new TypeAllocation(entry.Key, entry.Value)) + .ToImmutableList()); + } +} diff --git a/src/MeshWeaver.Hosting/ProcessLiveness.cs b/src/MeshWeaver.Hosting/ProcessLiveness.cs index e2466d6c0a..46eb0dc8d3 100644 --- a/src/MeshWeaver.Hosting/ProcessLiveness.cs +++ b/src/MeshWeaver.Hosting/ProcessLiveness.cs @@ -204,6 +204,75 @@ public static TimeSpan PeriodOf(string? configured) /// One day — a cadence past this is a typo, and the instrument would publish nothing. public static readonly TimeSpan MaximumPeriod = TimeSpan.FromDays(1); + /// + /// Heap growth inside ONE tick that makes the heartbeat say what was allocated (MeshWeaver#5555). + /// The steps being hunted are 2–10 GiB inside 100 s, i.e. at least this much in some + /// 10 s tick; the ordinary post-warm-up floor moves by tens of MiB per HOUR, so a window this + /// large is never routine and the line stays rare. + /// + public const long HeapStepThresholdBytes = 512L * 1024 * 1024; + + /// + /// The [HEAPSTEP] line for a tick whose heap grew by at least + /// since the previous tick, naming the types the runtime + /// sampled as allocated in that window; null for every other tick. + /// + /// 🚨 Conditional on purpose, unlike the [LIVENESS] line. The liveness line + /// must print unconditionally because its ABSENCE is a reading. This line is a second reading + /// ABOUT a tick the liveness line already published — its absence means "the heap did not step in + /// that tick", which the liveness line's own heap= already says. + /// + /// The previous tick's sample, or null on the first tick (which never reports). + /// This tick's sample. + /// What was sampled as allocated since the previous tick, or + /// null when this process has no running sampler — two different sentences, because "the + /// sampler ran and saw nothing" and "there is no sampler" are different readings. + /// The line, or null when the heap did not step. + public static string? DescribeHeapStep( + ProcessLivenessSample? previous, ProcessLivenessSample current, AllocationWindow? allocations) + { + if (previous is null) + return null; + var growth = current.HeapBytes - previous.HeapBytes; + if (growth < HeapStepThresholdBytes) + return null; + + var line = new System.Text.StringBuilder(512) + .Append(CultureInfo.InvariantCulture, + $"[HEAPSTEP] tick={current.TickSeq} heap={Gib(previous.HeapBytes)}→{Gib(current.HeapBytes)} (+{Gib(growth)}) in {Seconds(current.Elapsed - previous.Elapsed)}"); + + if (allocations is null) + return line.Append( + " — the allocation sampler is NOT running in this process, so this line cannot name " + + "the allocator.") + .ToString(); + if (allocations.TotalBytes <= 0) + return line.Append( + " — the sampler is running but sampled NO allocation in this window, so this line " + + "cannot name the allocator.") + .ToString(); + + line.Append(CultureInfo.InvariantCulture, + $"; sampled allocation in the window {Gib(allocations.TotalBytes)}, heaviest types:"); + foreach (var type in allocations.Top) + line.Append(CultureInfo.InvariantCulture, + $" {type.TypeName}={Gib(type.Bytes)} ({Share(type.Bytes, allocations.TotalBytes)})"); + return line + .Append(". Allocated, not retained: the leading type is the candidate for what the step holds.") + .ToString(); + } + + private static string Gib(long bytes) => + string.Create(CultureInfo.InvariantCulture, $"{bytes / (double)(1L << 30):0.00}GiB"); + + private static string Seconds(TimeSpan value) => + string.Create(CultureInfo.InvariantCulture, $"{value.TotalSeconds:0.00}s"); + + private static string Share(long part, long whole) => + whole <= 0 + ? "n/a" + : string.Create(CultureInfo.InvariantCulture, $"{100.0 * part / whole:0}%"); + /// The production probe: what the runtime says right now. /// This tick's number. /// The heartbeat's monotonic clock at this tick. diff --git a/src/MeshWeaver.Hosting/ProcessLivenessHeartbeatService.cs b/src/MeshWeaver.Hosting/ProcessLivenessHeartbeatService.cs index 236203443a..fa0030fb3b 100644 --- a/src/MeshWeaver.Hosting/ProcessLivenessHeartbeatService.cs +++ b/src/MeshWeaver.Hosting/ProcessLivenessHeartbeatService.cs @@ -84,6 +84,10 @@ private void Run(TimeSpan period) // Monotonic on purpose. Wall time steps (NTP, a VM resume) and would forge an overrun. var clock = Stopwatch.StartNew(); var slice = period < StopCheckSlice ? period : StopCheckSlice; + // The allocation sampler that lets a heap step name its allocator (MeshWeaver#5555). Owned by + // this thread for the life of the host; a sampler that cannot start leaves the heartbeat + // exactly as it was, and the [HEAPSTEP] line then SAYS it could not name anything. + var sampler = StartSampler(); ProcessLivenessSample? previous = null; var tick = 0L; var due = period; @@ -102,8 +106,12 @@ private void Run(TimeSpan period) { var sample = ProcessLiveness.Probe(++tick, clock.Elapsed); var reading = ProcessLiveness.Read(previous, sample, period); + var step = ProcessLiveness.DescribeHeapStep( + previous, sample, sampler?.Drain()); previous = sample; logger.LogInformation("{Reading}", reading.Describe()); + if (step is not null) + logger.LogWarning("{HeapStep}", step); } catch (Exception exception) { @@ -113,6 +121,23 @@ private void Run(TimeSpan period) tick); } } + + sampler?.Dispose(); + } + + private AllocationByTypeSampler? StartSampler() + { + try + { + return new AllocationByTypeSampler(); + } + catch (Exception exception) + { + logger.LogWarning(exception, + "[LIVENESS] the allocation sampler could not be started; a heap step in this process " + + "will be reported without the types that were allocated in it."); + return null; + } } } diff --git a/test/MeshWeaver.Hosting.Test/HeapStepNamesItsAllocatorTest.cs b/test/MeshWeaver.Hosting.Test/HeapStepNamesItsAllocatorTest.cs new file mode 100644 index 0000000000..7770c7fd8a --- /dev/null +++ b/test/MeshWeaver.Hosting.Test/HeapStepNamesItsAllocatorTest.cs @@ -0,0 +1,193 @@ +using System; +using System.Collections.Immutable; +using System.Linq; +using System.Reactive.Linq; +using System.Threading.Tasks; +using MeshWeaver.Fixture; +using MeshWeaver.Reactive.Assertions; +using Xunit; + +namespace MeshWeaver.Hosting.Test; + +/// +/// 🚨 MeshWeaver#5555: memex-cloud replicas take multi-GiB LIVE heap steps (+2 to +10 GiB inside +/// one 100 s [LIVENESS] sample, on several replicas within seconds) and one of them died of +/// OutOfMemoryException — and no reading anybody could take named WHAT was allocated. A heap +/// dump restarts a replica this size, and nobody is at the pod when a step lands. These tests pin the +/// in-band instrument: a tick whose heap grew by +/// or more names the types the runtime sampled as allocated in that window. +/// +public class HeapStepNamesItsAllocatorTest +{ + private static ProcessLivenessSample Sample(long tick, double elapsedSeconds, long heapBytes) => + new(tick, TimeSpan.FromSeconds(elapsedSeconds), 1, 1, 1, TimeSpan.Zero, heapBytes, false, 8, 0, 100); + + private const long Gib = 1L << 30; + + private static readonly AllocationWindow AStep = new( + 6 * Gib, + ImmutableList.Create( + new TypeAllocation("System.Byte[]", 5 * Gib), + new TypeAllocation("System.String", Gib))); + + [Fact] + public void AStepTick_NamesTheHeaviestTypesAllocatedInIt() + { + var line = ProcessLiveness.DescribeHeapStep( + Sample(40, 400, 2 * Gib), Sample(41, 410, 8 * Gib), AStep); + + line.Should().NotBeNull("the heap grew by 6 GiB inside one tick"); + line.Should().StartWith("[HEAPSTEP] tick=41 heap=2.00GiB→8.00GiB (+6.00GiB) in 10.00s"); + line.Should().Contain("System.Byte[]=5.00GiB (83%)"); + line.Should().Contain("System.String=1.00GiB (17%)"); + line!.IndexOf("System.Byte[]", StringComparison.Ordinal) + .Should().BeLessThan(line.IndexOf("System.String", StringComparison.Ordinal), + "the heaviest type is named first"); + } + + /// + /// The NEGATIVE control for the line above: the same window over a tick whose heap did NOT step + /// reports nothing — the line is rare by construction, never a second heartbeat. + /// + [Fact] + public void AnOrdinaryTick_ReportsNothing_EvenWithHeavyAllocation() + { + ProcessLiveness.DescribeHeapStep( + Sample(40, 400, 2 * Gib), Sample(41, 410, 2 * Gib + ProcessLiveness.HeapStepThresholdBytes - 1), AStep) + .Should().BeNull("growth one byte short of the threshold is not a step"); + ProcessLiveness.DescribeHeapStep(null, Sample(1, 10, 8 * Gib), AStep) + .Should().BeNull("the first tick has nothing to have grown from"); + } + + /// + /// A host whose sampler did not start still reports the step — and says it cannot name the + /// allocator, rather than printing an empty list that reads as "nothing was allocated". + /// + [Fact] + public void AStepWithoutSamples_SaysItCannotNameTheAllocator_AndWhy() + { + ProcessLiveness.DescribeHeapStep( + Sample(40, 400, Gib), Sample(41, 410, 3 * Gib), null) + .Should().Contain("the allocation sampler is NOT running in this process"); + ProcessLiveness.DescribeHeapStep( + Sample(40, 400, Gib), Sample(41, 410, 3 * Gib), AllocationWindow.Empty) + .Should().Contain("the sampler is running but sampled NO allocation in this window"); + } + + /// + /// A sample recorded while a drain takes the window is never lost: every byte recorded ends up + /// in exactly one drained window (Copilot review on #5665 — a mutable map swapped by reference + /// could take an add after the drain had read it). + /// + [Fact] + public void ConcurrentRecordAndDrain_LoseNoSample() + { + const int writers = 4, perWriter = 50_000; + // 🚨 The race is measured on the WHOLE taken window (TakeWindow), never on Drain's Top + // summary. The sampler is live, so every test in this host feeds it real ~100 KB samples, + // and Drain reports only the TopTypes heaviest types: reading the marker out of Top lost it + // whenever a window ranked it below other types — 187,818 of 200,000 on queue run + // 36016772968 — a loss in the TEST's reading, not in the sampler. The noise thread makes + // that condition present on every run instead of only on a busy CI host. + RecordAgainstTakeUnderNoise(writers, perWriter) + .Should().Be(writers * perWriter, "every recorded sample lands in exactly one taken window"); + } + + /// + /// Records one-byte marker samples from each of + /// threads while a noise thread records heavier types and the calling + /// thread takes the window in a loop; returns the marker bytes the takes held. + /// + internal static long RecordAgainstTakeUnderNoise(int writers, int perWriter) + { + using var sampler = new AllocationByTypeSampler(); + const string type = "ConcurrentRecordAndDrainMarker"; + var noiseTypes = Enumerable.Range(0, 2 * AllocationByTypeSampler.TopTypes) + .Select(i => $"Noise{i}").ToArray(); + var takenBytes = 0L; + var done = 0; + var noise = new System.Threading.Thread(() => + { + while (System.Threading.Volatile.Read(ref done) < writers) + foreach (var n in noiseTypes) + sampler.Record(n, 100 * 1024); + }); + var threads = Enumerable.Range(0, writers).Select(_ => new System.Threading.Thread(() => + { + for (var i = 0; i < perWriter; i++) + sampler.Record(type, 1); + System.Threading.Interlocked.Increment(ref done); + })).ToArray(); + noise.Start(); + foreach (var t in threads) + t.Start(); + while (System.Threading.Volatile.Read(ref done) < writers) + takenBytes += sampler.TakeWindow().GetValueOrDefault(type); + foreach (var t in threads) + t.Join(); + noise.Join(); + takenBytes += sampler.TakeWindow().GetValueOrDefault(type); + return takenBytes; + } + + /// + /// Drain's summary is the taken window ranked: heaviest first, at most + /// types, and a total over EVERY type — so a type + /// that falls out of Top is still counted in the total. + /// + [Fact] + public void Drain_RanksTheWindow_AndTotalsEveryType() + { + using var sampler = new AllocationByTypeSampler(); + const long heavy = 1L << 40; // heavier than anything the runtime samples into one window here + const int types = 2 * AllocationByTypeSampler.TopTypes; + for (var i = 0; i < types; i++) + sampler.Record($"Ranked{i:D2}", heavy + i); + + var window = sampler.Drain(); + + window.Top.Count.Should().Be(AllocationByTypeSampler.TopTypes); + window.Top[0].TypeName.Should().Be($"Ranked{types - 1:D2}", "the heaviest type is first"); + (window.TotalBytes >= types * heavy).Should().BeTrue("the total counts the types Top leaves out"); + } + + /// + /// The live half: the runtime's own GCAllocationTick events reach the sampler and are + /// attributed to the type that was allocated. Positive control for the pure tests above — a + /// sampler that received nothing would make every real [HEAPSTEP] line say "cannot name". + /// + [Fact] + public async Task TheSampler_AttributesSampledAllocationToTheTypeAllocated() + { + using var sampler = new AllocationByTypeSampler(); + // The runtime prints a NESTED type by its own name (measured: "HeapStepMarker[]", no + // namespace and no enclosing type), so match on the suffix the runtime is certain to print. + var marker = nameof(HeapStepMarker) + "[]"; + static bool IsMarker(TypeAllocation t) => t.TypeName.EndsWith(nameof(HeapStepMarker) + "[]", StringComparison.Ordinal); + + // Before allocating: whatever the process sampled so far, the marker is not in it. + sampler.Drain().Top.Should().NotContain(IsMarker, + "nothing has allocated a HeapStepMarker array yet"); + + // ~160 MiB of the marker type, kept reachable until the reading is taken. + var held = Enumerable.Range(0, 200).Select(_ => new HeapStepMarker[100_000]).ToArray(); + + // Samples arrive on the runtime's event dispatch thread, so drain until they have landed. + // Each drain starts a new window, so the per-type totals are summed across drains. + var attributed = await Observable.Interval(TimeSpan.FromMilliseconds(100)).StartWith(0L) + .Select(_ => sampler.Drain()) + .Scan(0L, (sum, w) => sum + w.Top.Where(IsMarker).Sum(t => t.Bytes)) + .Where(sum => sum >= 64L * 1024 * 1024) + .FirstAsync() + .Should().Within(TestTimeouts.Convergence) + .Emit($"~160 MiB of {marker} was allocated, so the runtime's sampled allocation events must attribute a large share of it to that type"); + + attributed.Should().BeGreaterThanOrEqualTo(64L * 1024 * 1024); + GC.KeepAlive(held); + } + + private sealed class HeapStepMarker + { + } + +}