Inconsistent MemoryCache stats

[verdie-g]

Description

The stats provided by MemoryCache might randomly decrease for a short time when a thread dies.

That problem did not occur to me in production but I would like to use a similar pattern in my library, so I would be interested to double check that the pattern is valid.

Reproduction Steps

1. A thread dies
2. The thread and thread locals get collected
3. The WeakReference in MemoryCache._allStats should now point to null
4. During that time, the thread local stats is not referenced by the _allStats list anymore and is not in the dead threads accumulator either
5. The Stats finalizer is called and the value of the thread counter is now added to the accumulators.

Here is some code reproducing the problem

using Microsoft.Extensions.Caching.Memory;

MemoryCache cache = new(new MemoryCacheOptions { TrackStatistics = true });

void RunThread()
{
    Thread t = new(() =>
    {
        for (int j = 0; j < 10_000; j += 1)
        {
            _ = cache.Get("");
        }

        RunThread();
    })
    {
        Name = "Cache Worker",
    };
    t.Start();
}

for (int i = 0; i < Environment.ProcessorCount - 1; i += 1)
{
    RunThread();
}

Thread integrityThread = new(() =>
{
    long lastValue = -1;
    while (true)
    {
        long newValue = cache.GetCurrentStatistics()!.TotalMisses;
        if (newValue < lastValue)
        {
            Console.WriteLine($"{DateTime.Now:HH:mm:ss.fff} ERROR: total misses decreased from {lastValue} to {newValue} (-{lastValue - newValue})");
        }

        lastValue = newValue;
    }
})
{
    Name = "Stats Integrity Checker"
};
integrityThread.Start();
integrityThread.Join();

prints

12:33:56.685 ERROR: total misses decreased from 15228455 to 8638696 (-6589759)
12:33:57.135 ERROR: total misses decreased from 36542054 to 9262055 (-27279999)
12:33:57.614 ERROR: total misses decreased from 71470000 to 62226058 (-9243942)
12:33:57.635 ERROR: total misses decreased from 68743304 to 49932686 (-18810618)
12:33:58.084 ERROR: total misses decreased from 99334439 to 90553748 (-8780691)
12:33:58.178 ERROR: total misses decreased from 105862703 to 96402589 (-9460114)
12:33:58.224 ERROR: total misses decreased from 109891914 to 84536179 (-25355735)
12:33:58.719 ERROR: total misses decreased from 144071687 to 134984002 (-9087685)
12:33:58.755 ERROR: total misses decreased from 146512384 to 117584531 (-28927853)
12:33:59.307 ERROR: total misses decreased from 182709797 to 173511034 (-9198763)
12:33:59.318 ERROR: total misses decreased from 179256370 to 150150238 (-29106132)
12:33:59.810 ERROR: total misses decreased from 217835394 to 208725505 (-9109889)
12:33:59.831 ERROR: total misses decreased from 217951354 to 192014222 (-25937132)

Prometheus counters are expected to be strictly monotonic increasing. A counter being decreased will be interpreted as a counter reset and will impact the rate computation.

Expected behavior

The MemoryCache stats should always increase and never decrease.

Actual behavior

The MemoryCache stats might decrease in some case.

Configuration

.NET: net9.0
OS: Mac OS Sequoia 15.3.2
Architecture: ARM64

[dotnet-policy-service]

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

[verdie-g]

@maryamariyan @tarekgh could you have a look at this issue 🙏

Again, I'm not sure this is a real problem but I'm really interested by this pattern to have a low-cost Interlocked.Increment.

[tarekgh]

@adamsitnik @jozkee could you please help looking at this issue? Thanks!

[jeffhandley]

Thank you for a good explanation, @verdie-g. I do not expect our team will be able to investigate this during .NET 10, so I'm marking it as help wanted [up-for-grabs] Good issue for external contributors and moving it to the Future milestone. I think the trickiest part will be setting up a minimal and reliable repro that can be used to validate a change on this.

[verdie-g]

@jeffhandley I've edited my issue to provide a minimal repo. Could you please upgrade this issue to a bug 🙏

[noahfalk]

That problem did not occur to me in production but I would like to use a similar pattern in my library, so I would be interested to double check that the pattern is valid.

I think you are accurate that as-is there is a bug. A couple potential ways the bug could be fixed:

1. Instead of having the ThreadLocal point to the Stats directly, have the ThreadLocal point to some StatsHandle that has a reference to Stats inside. Then change the _allStats to be List and a member of Stats is a WeakReference to the StatsHandle. This way when the thread exits the Stats object doesn't leave the list immediately. The WeakReference allows it to be detected as dead and pruned eventually at the same time it is copied over to the accumulated stats. Pruning the list whenever a new thread is added would probably be reasonable.

2. Add a Stats _lastStats field in addition to the accumulated stats which stores the last values reported by Sum(). If the internals of Sum() ever computes numbers that are less than _lastStats, return _lastStats instead. This isn't as accurate as (1), but it at least guarantees the results never decrease during the window where a dead thread's stats aren't included in either _allStats or _accumulatedStats.