Output Cache memory continually grows, PinnedBlockMemoryPool never releases memory

ww2406 commented 1 month ago

Is there an existing issue for this?

[X] I have searched the existing issues

Describe the bug

I believe Output Caching is affected by a similar issue as #55490. I've been experiencing issues with large size strings (~ 5 MB). I observed when comparing #55490 that I don't experience the issue to the same extent when using IIS (i.e., it is magnified by Kestrel). However, when I add Output Caching, I experience the same issue on IIS with bytes retained by MemoryPoolBlock and PinnedBlockMemoryPool.

Memory Profile with Output Caching on IIS. I did a forced GC at 1m40 with no change in memory.

Byte ownership with Output Caching on IIS:

Memory Profile without Output Caching on IIS. I did a forced GC at about 0m40 with an approximate 50% drop in memory.

There are still some bytes owned, but significantly less than without Output Caching.

This is why I believe it is related to but distinct from the other issue.

Expected Behavior

When load decreases, memory is released.

Steps To Reproduce

JMeter 50 threads, 10 sec ramp up against

using Microsoft.AspNetCore.OutputCaching;

var builder = WebApplication.CreateBuilder(args);

// Add services to the container.
// Learn more about configuring Swagger/OpenAPI at https://aka.ms/aspnetcore/swashbuckle
builder.Services.AddEndpointsApiExplorer();
builder.Services.AddSwaggerGen();
builder.Services.AddOutputCache();

var app = builder.Build();

// Configure the HTTP request pipeline.
if (app.Environment.IsDevelopment())
{
    app.UseSwagger();
    app.UseSwaggerUI();
}

app.UseHttpsRedirection();

app.UseOutputCache();

app.MapGet("/test", [OutputCache(Duration = 300)] () =>
{
    var s = new string('x', 5 * 1024 * 1024);
    return s;
});

app.Run();

Exceptions (if any)

No response

.NET Version

8.0.204

Anything else?

.NET SDK: Version: 8.0.204 Commit: c338c7548c Workload version: 8.0.200-manifests.9f663350

Runtime Environment: OS Name: Windows OS Version: 10.0.22631 OS Platform: Windows RID: win-x64 Base Path: C:\Program Files\dotnet\sdk\8.0.204\

.NET workloads installed: [maui-ios] Installation Source: VS 17.7.34024.191 Manifest Version: 8.0.3/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json Install Type: FileBased

[maui-android] Installation Source: VS 17.7.34024.191 Manifest Version: 8.0.3/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json Install Type: FileBased

[android] Installation Source: VS 17.7.34024.191 Manifest Version: 34.0.43/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.android\34.0.43\WorkloadManifest.json Install Type: FileBased

[ios] Installation Source: VS 17.7.34024.191 Manifest Version: 17.0.8478/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.ios\17.0.8478\WorkloadManifest.json Install Type: FileBased

[maui-windows] Installation Source: VS 17.7.34024.191 Manifest Version: 8.0.3/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json Install Type: FileBased

[maui-maccatalyst] Installation Source: VS 17.7.34024.191 Manifest Version: 8.0.3/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maui\8.0.3\WorkloadManifest.json Install Type: FileBased

[maccatalyst] Installation Source: VS 17.7.34024.191 Manifest Version: 17.0.8478/8.0.100 Manifest Path: C:\Program Files\dotnet\sdk-manifests\8.0.100\microsoft.net.sdk.maccatalyst\17.0.8478\WorkloadManifest.json Install Type: FileBased

Host: Version: 8.0.4 Architecture: x64 Commit: 2d7eea2529

.NET SDKs installed: 6.0.302 [C:\Program Files\dotnet\sdk] 7.0.400 [C:\Program Files\dotnet\sdk] 8.0.204 [C:\Program Files\dotnet\sdk]

.NET runtimes installed: Microsoft.AspNetCore.App 6.0.7 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 6.0.21 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 7.0.10 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 8.0.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.NETCore.App 6.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.21 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 7.0.10 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 8.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.WindowsDesktop.App 6.0.7 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.21 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 7.0.10 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 8.0.4 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found: x86 [C:\Program Files (x86)\dotnet] registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables: Not set

global.json file: Not found

Learn more: https://aka.ms/dotnet/info

Download .NET: https://aka.ms/dotnet/download

davidfowl commented 1 month ago

Do you see the same behavior when you allocate the string once and write it in chunks each request? What you’re doing in the above example is just not good in general. Even enough the pool doesn’t clean up, steaming the response is what will lead to good memory usage an good performance all up.

ww2406 commented 1 month ago

Yes, I explored last night with using streaming and observe the same effect -- without output caching, the memory is eventually freeable while with output caching, GC never releases it. I added another to see if allocating the string once makes a difference and it does not.

In the production use case, the string is retrieved from an IMemoryCache that is updated on an interval by a BackgroundService, and this was my attempt at figuring out if the holding was related to the memory cache or an issue with the framework itself.

Streaming with allocation per request

app.MapGet("/test2", [OutputCache(Duration = 300)] async  (context) =>
{
    var s = new string('x', 5 * 1024 * 1024);
    int len = 0;
    while (len < s.Length)
    {
        await context.Response.WriteAsync(s.Substring(len, Math.Min(20000, s.Length - len)));
        len += 20000;
    }

    await context.Response.CompleteAsync();
});

Streaming with one allocation

string sOnce = new string('x', 5 * 1024 * 1024);

app.MapGet("/test3", [OutputCache(Duration = 300)] async  (context) =>
{
    int len = 0;
    while (len < sOnce.Length)
    {
        await context.Response.WriteAsync(sOnce.Substring(len, Math.Min(20000, sOnce.Length - len)));
        len += 20000;
    }

    await context.Response.CompleteAsync();
});

davidfowl commented 1 month ago

Can you share the profile when you are streaming a signal string? Can you also attempt to convert this string into a byte[] and write that in chunks? Generally it’s fine to store a large string or byte[]. Output caching does its best to store chunks even if they are all in memory to avoid excessive LOH storage.

Can you run this with dotnet counters so you can observe if GCs are indeed happening?

PS: You don’t need to call CompleteAsync

ww2406 commented 1 month ago

profile from single allocated string

profile with byte[]

byte[] bString = Encoding.ASCII.GetBytes(sOnce);

app.MapGet("/test4", [OutputCache(Duration = 300)] async  (context) =>
{
    int len = 0;
    while (len < bString.Length)
    {
        int stop = Math.Min(20000, bString.Length - len);
        await context.Response.BodyWriter.WriteAsync(bString.AsMemory()[len..stop]);
        len += 20000;
    }
});

Let me know if there's a better way to implement the bytes streaming...

Can you run this with dotnet counters so you can observe if GCs are indeed happening?

It's a little hard to tell, but the small yellow lines in the memory profiles from dotMemory in Rider indicate when GC is happening. Definitely GC doesn't get triggered right away, but when I manually trigger it through dotMemory, with no output caching 50%+ of memory is freed, while there is a minimal change when output caching is added. Does dotnet counters add anything additional that would be helpful to see?

no output caching

w/ output caching

PS: You don’t need to call CompleteAsync

Thanks for the tip!

dotnet / aspnetcore