Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
146 changes: 146 additions & 0 deletions src/MeshWeaver.Hosting/AllocationByTypeSampler.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,146 @@
using System.Collections.Immutable;
using System.Diagnostics.Tracing;

namespace MeshWeaver.Hosting;

/// <summary>Sampled allocation volume of one type inside one heartbeat window.</summary>
/// <param name="TypeName">The runtime's name for the allocated type, e.g. <c>System.Byte[]</c>.</param>
/// <param name="Bytes">The sampled bytes attributed to it (each sample stands for ~100&#160;KB).</param>
public sealed record TypeAllocation(string TypeName, long Bytes);

/// <summary>
/// What the process allocated between two heartbeat ticks, by type, as the runtime sampled it.
/// </summary>
/// <param name="TotalBytes">Every sampled byte in the window, across all types.</param>
/// <param name="Top">The heaviest types, largest first.</param>
public sealed record AllocationWindow(long TotalBytes, ImmutableList<TypeAllocation> Top)
{
/// <summary>A window in which nothing was sampled — also what a host without the sampler reads.</summary>
public static readonly AllocationWindow Empty = new(0, ImmutableList<TypeAllocation>.Empty);
}

/// <summary>
/// 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.
///
/// <para>🚨 <b>Why an in-process sampler and not a heap dump.</b> 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 <c>dotnet-dump collect --type Heap</c> froze the process for ~106&#160;s,
/// past the liveness budget, and restarted the container (<c>Doc/Architecture/PortalHeapIsHubs</c>).
/// 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
/// <c>GCAllocationTick</c> event per ~100&#160;KB allocated, carrying the type — so listening to
/// those costs one event per 100&#160;KB and names the type in-band, at the step, in the log the
/// fleet already keeps.</para>
///
/// <para>🚨 <b>Allocated is not retained.</b> 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.</para>
///
/// <para>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.</para>
/// </summary>
public sealed class AllocationByTypeSampler : EventListener
{
/// <summary>The runtime's event source.</summary>
public const string RuntimeProviderName = "Microsoft-Windows-DotNETRuntime";

/// <summary>The <c>GC</c> keyword — the one <c>GCAllocationTick</c> is raised under.</summary>
private const EventKeywords GcKeyword = (EventKeywords)0x1;

/// <summary><c>GCAllocationTick</c>'s event id (every version of it).</summary>
private const int AllocationTickEventId = 10;

/// <summary>How many types a window reports. The step is one or two types, never forty.</summary>
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<string, long> window = ImmutableDictionary.Create<string, long>(StringComparer.Ordinal);

/// <inheritdoc />
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);
}

/// <inheritdoc />
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);
}

/// <summary>Adds one sample to the current window.</summary>
/// <param name="typeName">The allocated type.</param>
/// <param name="bytes">The sampled bytes.</param>
internal void Record(string typeName, long bytes) =>
ImmutableInterlocked.AddOrUpdate(ref window, typeName, bytes, (_, sum) => sum + bytes);

/// <summary>
/// The window since the previous drain, heaviest types first, and a fresh window started.
/// </summary>
/// <returns>What was sampled since the last call.</returns>
public AllocationWindow Drain() => Summarize(TakeWindow());

/// <summary>
/// Takes the WHOLE window since the previous take — every type, not only the heaviest — and
/// starts a fresh one. <see cref="Drain"/> is this plus the Top-<see cref="TopTypes"/> summary;
/// the record/drain race is a property of this take alone, so it is measured here, where no
/// ranking can hide a sample.
/// </summary>
/// <returns>Every type sampled since the last take, with its summed bytes.</returns>
internal ImmutableDictionary<string, long> TakeWindow() =>
Interlocked.Exchange(ref window, window.Clear());

private static AllocationWindow Summarize(ImmutableDictionary<string, long> 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());
}
}
69 changes: 69 additions & 0 deletions src/MeshWeaver.Hosting/ProcessLiveness.cs
Original file line number Diff line number Diff line change
Expand Up @@ -204,6 +204,75 @@ public static TimeSpan PeriodOf(string? configured)
/// <summary>One day — a cadence past this is a typo, and the instrument would publish nothing.</summary>
public static readonly TimeSpan MaximumPeriod = TimeSpan.FromDays(1);

/// <summary>
/// Heap growth inside ONE tick that makes the heartbeat say what was allocated (MeshWeaver#5555).
/// The steps being hunted are 2–10&#160;GiB inside 100&#160;s, i.e. at least this much in some
/// 10&#160;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.
/// </summary>
public const long HeapStepThresholdBytes = 512L * 1024 * 1024;

/// <summary>
/// The <c>[HEAPSTEP]</c> line for a tick whose heap grew by at least
/// <see cref="HeapStepThresholdBytes"/> since the previous tick, naming the types the runtime
/// sampled as allocated in that window; <c>null</c> for every other tick.
///
/// <para>🚨 <b>Conditional on purpose, unlike the <c>[LIVENESS]</c> line.</b> 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 <c>heap=</c> already says.</para>
/// </summary>
/// <param name="previous">The previous tick's sample, or null on the first tick (which never reports).</param>
/// <param name="current">This tick's sample.</param>
/// <param name="allocations">What was sampled as allocated since the previous tick, or
/// <c>null</c> 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.</param>
/// <returns>The line, or null when the heap did not step.</returns>
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}%");

/// <summary>The production probe: what the runtime says right now.</summary>
/// <param name="tickSeq">This tick's number.</param>
/// <param name="elapsed">The heartbeat's monotonic clock at this tick.</param>
Expand Down
25 changes: 25 additions & 0 deletions src/MeshWeaver.Hosting/ProcessLivenessHeartbeatService.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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)
{
Expand All @@ -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;
}
}
}

Expand Down
Loading
Loading