Allocation Rate / GC.GetTotalAllocatedBytes() stops updating

[theolivenbaum]

Description

When monitoring the "Allocation Rate" event counter, we often see the value showing zeros for a very long time in our logs:

And it seems like it is due to the fact that GC.GetTotalAllocatedBytes() is returning a constant value (for example:
1198079260376 on a recent test). This is on a memory intensive application (container with >300GB RAM) with high memory allocation rate.

Any ideas if this is expected behaviour?

Reproduction Steps

N/A

Expected behavior

GC.GetTotalAllocatedBytes() updates with the latest value

Actual behavior

GC.GetTotalAllocatedBytes() stops updating

Regression?

As far as I know, this was not happening on .NET 9.0

Known Workarounds

No response

Configuration

No response

Other information

No response

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/gc
See info in area-owners.md if you want to be subscribed.

[theolivenbaum]

For reference, calling GC.GetTotalAllocatedBytes(true) does return a value that is still changing, and much lower than the value returned by GC.GetTotalAllocatedBytes():

GC.GetTotalAllocatedBytes(true) -> 723,187,864,416
GC.GetTotalAllocatedBytes() -> 1,198,079,260,376

The relevant source code seems to be here.

It doesn't seem to be an overflow issue as the variable used for accumulating the value is uint64_t (i.e. max value of 18,446,744,073,709,551,615)

[jkotas]

Any ideas if this is expected behaviour?

GetTotalAllocatedBytes returns an approximation. The raw approximation is computed without taking locks and thus it can fluctuate up and down. This fluctuation was confusing to people, and we have "fixed" the implementation to never return smaller value than what was returned before:

runtime/src/coreclr/vm/comutilnative.cpp

Lines 977 to 985 in c78f853

	uint64_t current_high = high_watermark;
	while (allocated_bytes > current_high)
	{
	uint64_t orig = InterlockedCompareExchange64((LONG64*)& high_watermark, allocated_bytes, current_high);
	if (orig == current_high)
	return allocated_bytes;
	current_high = orig;
	}

My guess is that the problem you are seeing is caused by a particularly bad high raw approximation that the extra logic in GetTotalAllocatedBytes cached and keeps returning. I expect that if you wait long enough GetTotalAllocatedBytes will start to return changing values again.

[jkotas]

particularly bad high raw approximation

I don't have ideas what can lead to it specifically and whether we can do something about it.

[theolivenbaum]

That does indeed happens, but from the two values above you can see it will take ~500GB of allocations to get back working. In practice it takes a very long time for it to start showing values again, and not so long for it to fail again.

Maybe a call to GC.GetTotalAllocatedBytes(true) should reset the value? This way we could detect this edge case in code and reset it automatically?

Or every N calls to GC.GetTotalAllocatedBytes() the cached value is reset?

[theolivenbaum]

Overnight, the issue happened about once to twice an hour, with two distinct weird patterns:

Normal measurements then nothing for a while again:

Large peak, then correct values for a few minutes (hard to see in the screenshot but after the first peak there were normal values for ~5 min), then nothing for another 25 minutes, followed by another large peak with correct measurements for a few more minutes:

Both cases seems strange based on the logic described above. In the first case, it seems like no large value got returned yet we stopped having new values. In the second case I would have expected the large peak to cause zeros immediately after due to the logic of never returning a value smaller than the previously returned one, but seems to not be the case.

[theolivenbaum]

Another question: Are there any real drawbacks from monitoring using GC.GetTotalAllocatedBytes(precise: true) ?

Just did a quick benchmark on this same machine, and it doesn't seem to be as bad as the documentation suggests it to be:

var sw = Stopwatch.StartNew();
var l = 0l;
for(int i = 0; i < 100; i++)
{
    l += GC.GetTotalAllocatedBytes(true);
}
sw.Stop();
Console.WriteLine($"Total Allocated:{l:n0} bytes\nAvg Allocated:{l/100f:n0} bytes");
Console.WriteLine($"Total Elapsed: {sw.ElapsedMilliseconds}ms\nAvg per call: {sw.ElapsedMilliseconds / 100f}ms");

Gives:

Total Allocated:  2,191,932,500,090,296 bytes 
Avg Allocated:        21,919,325,749,248 bytes
Total Elapsed:     3ms 
Avg per call:       0.03ms

I understand GC.GetTotalAllocatedBytes(false) is essentially free - but is there any real issue with repeatedly calling GC.GetTotalAllocatedBytes(true) instead to get a real metric besides the 0.03ms per call?

[VSadov]

There are cases like: GC provided a buffer to a thread (and incremented the metric in the heap), the thread used a few bytes and then exited. Internally GC rewinds the metric for the unused portion of the buffer, but for the public API pretends that "negative allocation" did not happen. This is relatively unusual.

If the app indeed allocates actively, the GC.GetTotalAllocatedBytes() should move forward. In arbitrarily chunks due to allocation buffering, but should move forward.

I could only explain this if the program somehow uses extremely huge thread-local allocation buffers or/and there are lots of threads as well.

Otherwise, it could be a bug in accumulating the count.

[VSadov]

Another question: Are there any real drawbacks from monitoring using GC.GetTotalAllocatedBytes(precise: true)

Precise computation suspends all the threads in the program for the duration of collecting the metric. Then it not only collects counts accumulated in heaps, but also visits every thread to get exactly where the threads are in terms of using their allocation buffers.

For some programs it can be a considerable expense.

[theolivenbaum]

@VSadov thanks for the explanation, that is indeed expensive then with potential side effects.

By the way, seems like I missed this previous issue on the topic: #118826, and maybe also somehow related: #106712

[theolivenbaum]

Regarding the question about threads: The application has ~150-200 threads in total across the threadpool + own threads (almost all idle at this point), and there seems to be no correlation between a sudden increase on threads count or the GC triggering a large collection:

And there's nothing happening that would explain a 1TB allocation spike, so it must be some issue in the calculation.