The Wayback Machine - https://web.archive.org/web/20211202013338/https://github.com/dotnet/aspnetcore/issues/38722
Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

.NET 6 Memory Leak/Issue #38722

Open
azampagl opened this issue Nov 30, 2021 · 11 comments
Open

.NET 6 Memory Leak/Issue #38722

azampagl opened this issue Nov 30, 2021 · 11 comments

Comments

@azampagl
Copy link

@azampagl azampagl commented Nov 30, 2021

Describe the bug

We're noticing a memory issue running a typical ASP.NET Core 6 website behind IIS on a Windows Server. After a few days the worker process (w3wp.exe) memory consumption grows from 2 gigs up to 25 gigs. Performing an IIS Stop / Start "fixes" the issue in the intermediate. I believe the issue is related to a FileWatcher that is not freeing up memory. We've had the issue since .NET 5 and noticed that someone else had a very similar issue (but not necessarily the same) found here #31125 and here #31219. It was supposedly fixed in .NET 6 which is why we upgraded, but we are still having the issue.

Here are some screenshots of dotMemory on the memory data dump when the production server got to 26gigs.

Top level snapshot.

01-process_dump

High level inspection page.

02-inspections

Drill down to the Byte[] array section (Similar Retention Section).

03-similar_retention_01

Drill down to the Byte[].

03-similar_retention_02

Drill down to the OverlappedData section (Instances).

04-instances_01

Drill down to an individual OverlappedData.

05-instances_02

To Reproduce

I have yet to been able to reproduce this on any of our team's development boxes. This only occurs on production which is making it hard to pinpoint.

Exceptions (if any)

None

Further technical details

  • ASP.NET Core version: 6.0.0
  • The IDE (VS / VS Code/ VS4Mac) you're running on, and its version: VS2022
  • Windows Server 2019 (latest updates)
  • SQL Server 2019 (Web Edition)
  • IIS 10.0
  • ASP.NET Core is running behind IIS in "InProcess"
  • Include the output of dotnet --info:
dotnet --info Output
.NET SDK (reflecting any global.json):
 Version:   6.0.100
 Commit:    9e8b04bbff

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.19042
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\6.0.100\

Host (useful for support):
  Version: 6.0.0
  Commit:  4822e3c3aa

.NET SDKs installed:
  3.1.120 [C:\Program Files\dotnet\sdk]
  3.1.201 [C:\Program Files\dotnet\sdk]
  3.1.300 [C:\Program Files\dotnet\sdk]
  3.1.301 [C:\Program Files\dotnet\sdk]
  3.1.403 [C:\Program Files\dotnet\sdk]
  3.1.415 [C:\Program Files\dotnet\sdk]
  5.0.104 [C:\Program Files\dotnet\sdk]
  5.0.209 [C:\Program Files\dotnet\sdk]
  5.0.303 [C:\Program Files\dotnet\sdk]
  5.0.400 [C:\Program Files\dotnet\sdk]
  5.0.401 [C:\Program Files\dotnet\sdk]
  5.0.403 [C:\Program Files\dotnet\sdk]
  6.0.100 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.All 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.19 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.20 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.21 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.8 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.10 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.12 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.19 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.20 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.21 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.8 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.10 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.12 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 3.1.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.4 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.5 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.19 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.20 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.21 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.8 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.9 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.10 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.12 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Including screenshots of the IIS config so we are on the same page / just in case there is something misconfigured that we are unaware of.

07_iis_01

08_iis_02

Discussion / Side Notes

  • I have yet to been able to reproduce this on any developer machine.
  • On the first dotMemory screenshot, notice the discrepancy between ".NET total" vs ".NET used". Looks like .NET is allocating more than it needs and then not releasing? On .NET 5 there was significantly more ".NET used", so at least there seems to be some improvement. Regardless, I don't think the app should be using 5gigs, let alone 25 gigs.
  • The FileWatcher consumptoin is what is concerning me. We don't use it anywhere in our code. And looking at our libraries, they don't appear to have any type of FileWatcher stuff either. My only though is that it is related to reloadOnChange during the CreateDefaultBuilder (https://github.com/dotnet/aspnetcore/blob/main/src/DefaultBuilder/src/WebHost.cs). Similar to issues #31125 and #31219 where they cleared the sources and everything was fine.
  • We don't do anything "crazy" in the sense of processing - it's a standard ASP.NET website with a SQL database using EF Core. We avoid most of the memory leak pitfalls (e.g. no event subscribing, etc). About the only non-trivial thing we do is run some processes in the background using a hosted service after a request is made. I have included the basic code below in case something pops out that is a big no-no. We more or less copy and pasted the code snippets from https://docs.microsoft.com/en-us/aspnet/core/fundamentals/host/hosted-services
  • Stackoverflow post that had a similar issue and resolved it by clearing his config.Sources in ConfigureAppConfiguration. https://stackoverflow.com/questions/66791228/net-5-ihost-filesystemwatcher-memory-leak
  • Tagging @davidfowl as he was the one who looked like he worked on the previous bug fix / similar issue. Was the fix for the previous issue (#31125) added to .NET6?

Code Snippets

Web.config

<configuration xmlns:xdt="http://schemas.microsoft.com/XML-Document-Transform">
    <system.webServer xdt:Transform="Replace">
        <modules runAllManagedModulesForAllRequests="false">
            <remove name="WebDAVModule" />
        </modules>
        <handlers>
            <add name="aspNetCore" path="*" verb="*" modules="AspNetCoreModuleV2" resourceType="Unspecified" />
        </handlers>
        <aspNetCore processPath="dotnet" arguments=".\App.dll" stdoutLogEnabled="true" stdoutLogFile="..\logs\aspnetcore\stdout" requestTimeout="00:05:00" hostingModel="InProcess">
            <environmentVariables>
                <environmentVariable name="ASPNETCORE_ENVIRONMENT" value="Production" />
                <environmentVariable name="ASPNETCORE_SUPPRESSSTATUSMESSAGES" value="true" />
            </environmentVariables>
        </aspNetCore>
    </system.webServer>
</configuration>

Program.cs

public class Program
    {
        /// <summary>
        ///
        /// </summary>
        public static void Main(string[] args)
        {
            CreateHostBuilder(args).Build().Run();
        }

        public static IHostBuilder CreateHostBuilder(string[] args)
        {
            return Host.CreateDefaultBuilder(args).ConfigureWebHostDefaults(webBuilder =>
            {
                webBuilder.ConfigureLogging((hostingContext, logging) =>
                {
                    logging.ClearProviders();
                    logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging"));
                    logging.AddEventLog(new EventLogSettings
                    {
                        LogName = "Application",
                        SourceName = hostingContext.Configuration["Name"]
                    });

                    switch (Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT"))
                    {
                        case "Production":
                            // Do nothing
                            break;
                        case "Backup":
                            logging.AddDebug();
                            break;
                        case "Staging":
                            logging.AddDebug();
                            break;
                        case "Development":
                            logging.AddDebug();
                            break;
                        default:
                            throw new Exception("Unsupported environment.");
                    }
                });

                webBuilder.UseStartup<Startup>();
            });
        }
    }

Startup.cs (only including this so you can see how to utilize a background hosted service)

...
services.AddDbContext<ApplicationDbContext>(options =>
                options.UseSqlServer(Configuration.GetConnectionString("DefaultConnection")));

...

services.AddScoped<IScopedWorker, ScopedWorker>();
services.AddSingleton<MySingletonThatAddsToBackground>();
// Follow the host service guide from microsoft.
services.AddHostedService<QueuedHostedService>();
services.AddSingleton<IBackgroundTaskQueue, BackgroundTaskQueue>();

MySingletonThatAddsToBackground.cs

public class MySingletonThatAddsToBackground
{
    private readonly IBackgroundTaskQueue _taskQueue;
    private readonly ILogger _logger;
    private readonly CancellationToken _cancellationToken;
    public IServiceProvider _services { get; }

    public MySingletonThatAddsToBackground(IServiceProvider services, IBackgroundTaskQueue taskQueue,
        ILogger<MonitorLoop> logger,
        IHostApplicationLifetime applicationLifetime)
    {
        _services = services;
        _taskQueue = taskQueue;
        _logger = logger;
        _cancellationToken = applicationLifetime.ApplicationStopping;
    }

    public void DoWorkBackground()
    {
        // Enqueue a background work item
        _taskQueue.QueueBackgroundWorkItem(async token =>
        {
            try
            {
                using (var scope = _services.CreateScope())
                {
                    var scopedWorker = scope.ServiceProvider.GetRequiredService<IScopedWorker>();

                    await scopedWorker.DoWork();
                }
            }
            catch (OperationCanceledException)
            {
                // Prevent throwing if the Delay is cancelled
            }
        });
    }
}

ScopedWorker.cs

public class ScopedWorker : IScopedWorker
{
    private readonly ApplicationDbContext _db;

    public ScopedWorker(ApplicationDbContext db)
    {
        _db = db;
    }

    public void DoWork()
    {
        var customers = _db.MyCustomers.ToListAsync();
        
        // Do stuff to customers.

        await _db.SaveChangesAsync();
    }
}

Questions

  • Should we not be running it in InProcess mode to get better dump data?
  • Should we utilize Workstation GC vs the default Server GC?
  • Should we be setting the private memory section on the IIS app pool? All this really does is recycle the app pool which doesn't really solve the issue. To my knowledge, there is no way to restrict an IIS process memory consumption.
  • I'm currently using dotMemory on a memory dump from the production box. Is there something else I should be doing to get better insight?
@pranavkm
Copy link
Contributor

@pranavkm pranavkm commented Nov 30, 2021

Out of curiosity, is the memory released if you force a GC? I believe dotMemory has an option to do that.

Loading

@azampagl
Copy link
Author

@azampagl azampagl commented Nov 30, 2021

@pranavkm The app is running in release/production mode and dotMemory is not available on the server. Although it is not advised, would running System.GC.Collect() (https://docs.microsoft.com/en-us/dotnet/api/system.gc.collect?view=net-6.0#System_GC_Collect) have the same effect you want?

Loading

@davidfowl
Copy link
Member

@davidfowl davidfowl commented Nov 30, 2021

Is the leak coming from those byte[] pinned by the FileSystemWatcher?

Loading

@azampagl
Copy link
Author

@azampagl azampagl commented Nov 30, 2021

@davidfowl I believe so... The main byte[] that is taking up 5gigs is pinned via "OverlappedData" from FileSystemWatcher. See screenshot. I'm kind of new to dotMemory, so if tell me how to navigate to what you're looking for I can do so (I can also zoom/team/share screen - whatever is easiest for your team).

09_pinning

Loading

@davidfowl
Copy link
Member

@davidfowl davidfowl commented Nov 30, 2021

That memory is pinned so it's not gonna go away with a GC. We need to figure out who is creating those. The best way to go about this would be to capture an allocation trace in production. It'll show you the stack that is causing these allocations.

https://github.com/Maoni0/mem-doc/blob/master/doc/.NETMemoryPerformanceAnalysis.md#how-to-collect-top-level-gc-metrics

https://docs.microsoft.com/en-us/dotnet/core/diagnostics/debug-memory-leak (though this is just the dump).

Where is this file system watcher rooted?

Loading

@azampagl
Copy link
Author

@azampagl azampagl commented Nov 30, 2021

@davidfowl I read your first link. I've put PerfView on the machine. If I'm understanding this correctly I should be able to just run

PerfView.exe /nogui /accepteula /KernelEvents=Process+Thread+ImageLoad /ClrEvents:GC+Stack /BufferSize:3000 /CircularMB:3000 collect

On the production server to capture the allocation trace? (I ran a quick sample and it generates a PerfViewGCCollectOnly.etl.zip file.)

I don't need to target the process ID (w3wp.exe) or anything?

In regards to the dump, is the dotnet-dump preferred over the normal windows memory dump?

Loading

@azampagl
Copy link
Author

@azampagl azampagl commented Dec 1, 2021

Details for the byte[] array set (some are duplicates from above)

10

11

12

13

14

Interesting that it's showing most of it is in Gen2, where 42mb is used/pinned, 5gb used/unpinned, 12.5G free but not released...

99

100_gen2_overview

Loading

@davidfowl
Copy link
Member

@davidfowl davidfowl commented Dec 1, 2021

I don't need to target the process ID (w3wp.exe) or anything?

No it collects the entire machine. If you use dotnet trace it'll require the pid

On the production server to capture the allocation trace? (I ran a quick sample and it generates a PerfViewGCCollectOnly.etl.zip file.)

Yes, you're trying to figure out where the allocations are coming from.

In regards to the dump, is the dotnet-dump preferred over the normal windows memory dump?

Either is fine.

Loading

@azampagl
Copy link
Author

@azampagl azampagl commented Dec 1, 2021

Unfortunately, the 12 hour PerfView collection I had didn't go well. When I opened it up in PerfView, it was missing the "“GC Heap Alloc Ignore Free (Coarse Sampling)” section. I don't know if it was because of the length of recording or file size. When I sample for say 30 minutes, it's available.

I did notice that after 7 hours, the size stayed at "6,300MB" exactly which was strange, but I let it keep running.

16

15

The process grew from 2gigs to about 11.5gigs over that 12 hours span during the night (theoretically our lower traffic time).

I've started a trace again this time using PerfView64 just in case and the /FocusProcess= argument when collecting to focus on the process. I'll report back in a few hours. I didn't want to do an app pool reset yet, so I've started the recording while the current process is sitting at 12gigs

Loading

@davidfowl
Copy link
Member

@davidfowl davidfowl commented Dec 1, 2021

@azampagl Do you have the trace still?

cc @Maoni0 @brianrob

Loading

@azampagl
Copy link
Author

@azampagl azampagl commented Dec 1, 2021

@davidfowl

Started the perfview monitoring at ~9:30AM EST when the process w3wp.exe was already at 12G (it had grown from 2G to 12G overnight). I recorded for 2.5 hours with the following command.

.\PerfView64 /nogui /accepteula /KernelEvents=Process+Thread+ImageLoad /ClrEvents:GC+Stack /BufferSize:3000 /CircularMB:3000 /FocusProcess=69368 collect

Breakdown
All final recordings stopped at ~11:59AM EST. The w3wp.exe process at the time was using 16.5G (so gained 4.5G in about 2.5 hours)

dotnet-dump (high level, I have more screenshots if you need)

14

10

11

12

13

PerView
01

02

03

04

05

06

Thoughts

  • Why is it not releasing the "free" memory from Gen2 (~7.67gigs)?
  • Strange that dotMemory is referencing the bytes with relation to the FileWatcher, but I see minimal mention of the FIleWatcher in the PerfView results.

Loading

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
3 participants