Memory leak when restarting host on aspnet core 5

[Leandro-Albano]

Describe the bug

After calling IHostApplicationLifetime.StopApplication() I am trying to build and start the IHost again. Inspecting the diagnostic tools on visual studio I can see that the memory goes up (a bit) every cycle, even trying to call System.GC.Collect().

To Reproduce

public class Program
{
    public static void Main(string[] args)
    {
        while (true)
        {
            using (var builder = CreateHostBuilder(args).Build())
            {
                builder.Start();
                builder.WaitForShutdown();
            }
            System.GC.Collect();
        }
    }

    public static IHostBuilder CreateHostBuilder(string[] args) =>
        Host.CreateDefaultBuilder(args)
            .ConfigureWebHostDefaults(webBuilder =>
            {
                webBuilder.Configure((IApplicationBuilder app) =>
                {
                    app.UseRouting();

                    app.UseEndpoints(endpoints =>
                    {
                        var lifetime = app.ApplicationServices.GetRequiredService<IHostApplicationLifetime>();

                        endpoints.MapGet("/stop", async context =>
                        {
                            lifetime.StopApplication();
                            await context.Response.WriteAsync("Hello World!");
                        });
                    });
                });
            });
}

Further technical details

• ASP.NET Core version: 5.0.0
• Include the output of dotnet --info

.NET SDK (reflecting any global.json):
 Version:   5.0.201
 Commit:    a09bd5c86c

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

Host (useful for support):
  Version: 5.0.4
  Commit:  f27d337295

.NET SDKs installed:
  2.1.509 [C:\Program Files\dotnet\sdk]
  2.1.511 [C:\Program Files\dotnet\sdk]
  3.0.101 [C:\Program Files\dotnet\sdk]
  3.1.201 [C:\Program Files\dotnet\sdk]
  5.0.100 [C:\Program Files\dotnet\sdk]
  5.0.103 [C:\Program Files\dotnet\sdk]
  5.0.201 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.All 2.1.13 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.15 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.13 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.15 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.0.1 [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.12 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.15 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.0.1 [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.12 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 3.0.1 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 3.1.12 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.4 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

• The IDE (VS / VS Code/ VS4Mac) you're running on, and its version
  VS 2019 (16.8.6)

[Tratcher]

How much memory after how many cycles? To prove it's a leak we'd want to see that it does not eventually plato or drop after hundreds of cycles. A GC does not guarantee process memory is returned to the OS.

Capturing a dump between cycles would be the best way to identify any leaked objects.

[Leandro-Albano]

I added a new endpoint witch dos not stop the app and made 100 calls to make sure the app was warmup, took a snapshot of the memory. Then I ran 100 more calls every 5 seconds to the endpoint that stops the app and it gets restarted and took another snapshot at the end. This was the result: (I don't know if there is an option to export it?) That is with the call to GC.

The same approach but without System.GC.Collect()

[davidfowl]

There's a known issue where ASP.NET Core doesn't clean up MemoryPoolSlabs #27394 but your issue I'm guessing is because you're holding onto references of the host on the stack in Main.

How many host instances are hanging around? Are any of them rooted? Disposing the host should clean up the entire memory pool leaving them memory to be reclaimed by the GC (eventually). Beyond that, there's more advanced analysis you can do to figure out why memory is being held onto (getting a memory dump after a gc and using dotnet dump analyze to look at the heap).

[Tratcher]

It sounds like you ran hundreds of iterations but the only thing with hundreds of instances in the Count column is RuntimeType.

[Leandro-Albano]

I should have ordered it, sorry about that, but this screenshot shows a comparison between 100 calls to stop and restart and then after 100 more. The server started at 80MB and after 200 calls it is on 160MB.

@Tratcher You are right RuntimeType is the one with more instances on count. Is that ok? No numbers there actually make sense compared to the number of cycles (200 now). I mean it does not show objects hanging around that match the number of calls.

@davidfowl it shows only 1 instance of the Host. I'll do what you suggested and get a memory dump after GC.

[Tratcher]

I don't know what RuntimeType is for, but since it says the count diff is going down rather than up there's not a persistent leak.

The server started at 80MB and after 200 calls it is on 160MB.

The process can reserve more memory than it's currently consuming. Cleaning up objects and releasing memory back to the OS are decoupled concerns.

[davidfowl]

RuntimeType is just the implementation of the abstraction Type.

[Leandro-Albano]

After running dotnet-dump I found that at least some objects count are increasing with the number of cycles, not sure if that is expected.

System.WeakReference`1[[System.IO.FileSystemWatcher,   System.IO.FileSystem.Watcher]]
System.IO.FileSystemWatcher+NormalizedFilterCollection+ImmutableStringList
System.IO.FileSystemWatcher+NormalizedFilterCollection
Microsoft.Win32.SafeHandles.SafeWaitHandle
System.Diagnostics.DiagnosticListener
System.Collections.Concurrent.ConcurrentDictionary`2+Tables[[Microsoft.Extensions.FileProviders.IPollingChangeToken,   Microsoft.Extensions.FileProviders.Physical],[Microsoft.Extensions.FileProviders.IPollingChangeToken,   Microsoft.Extensions.FileProviders.Physical]]
System.Collections.Concurrent.ConcurrentDictionary`2[[Microsoft.Extensions.FileProviders.IPollingChangeToken,   Microsoft.Extensions.FileProviders.Physical],[Microsoft.Extensions.FileProviders.IPollingChangeToken,   Microsoft.Extensions.FileProviders.Physical]]
System.IO.FileSystemWatcher+AsyncReadState
System.Func`1[[System.Threading.Timer,   System.Private.CoreLib]]
System.IO.ErrorEventHandler
System.IO.RenamedEventHandler
Microsoft.Extensions.FileProviders.Physical.PhysicalFilesWatcher
System.IO.FileSystemWatcher
System.Collections.Concurrent.ConcurrentDictionary`2+Node[[Microsoft.Extensions.FileProviders.IPollingChangeToken,   Microsoft.Extensions.FileProviders.Physical],[Microsoft.Extensions.FileProviders.IPollingChangeToken,   Microsoft.Extensions.FileProviders.Physical]][]

[Tratcher]

Is it a one-to-one growth? After 100 cycles you have 100 file watchers? What are the GC roots for the watchers?

[davidfowl]

After running dotnet-dump I found that at least some objects count are increasing with the number of cycles, not sure if that is expected.

Where are the object counts?

dumpheap -stat -live

[Leandro-Albano]

@Tratcher It's a 1-1 growth, but I got 101 instances because of the first run (I'm counting cycles as stop and run again).
When I ran again now I got just
I ran it again today and got just these 3 with 101 instances

System.WeakReference`1[[System.IO.FileSystemWatcher,   System.IO.FileSystem.Watcher]]
System.Diagnostics.DiagnosticListener
System.IO.FileSystemWatcher+AsyncReadState

gcroot for System.IO.FileSystemWatcher+AsyncReadState:

> gcroot -all 0000019b67aefbb8
HandleTable:
    00000198A7381570 (async pinned handle)
    -> 0000019B676B2358 System.Threading.OverlappedData
    -> 0000019B676B2310 System.Threading.ThreadPoolBoundHandleOverlapped
    -> 0000019B67AEFBB8 System.IO.FileSystemWatcher+AsyncReadState

gcroot for System.WeakReference`1[[System.IO.FileSystemWatcher, System.IO.FileSystem.Watcher]]:

> gcroot -all 0000019b67a09c68
HandleTable:
    00000198A7161518 (async pinned handle)
    -> 0000019B67A09CE8 System.Threading.OverlappedData
    -> 0000019B67A09CA0 System.Threading.ThreadPoolBoundHandleOverlapped
    -> 0000019B67A09C08 System.IO.FileSystemWatcher+AsyncReadState
    -> 0000019B67A09C68 System.WeakReference`1[[System.IO.FileSystemWatcher, System.IO.FileSystem.Watcher]]

Finalizer Queue:
    0000019B67A09C68
    -> 0000019B67A09C68 System.WeakReference`1[[System.IO.FileSystemWatcher, System.IO.FileSystem.Watcher]]

    0000019B67A09C80
    -> 0000019B67A09C80 System.Threading.PreAllocatedOverlapped
    -> 0000019B67A09CA0 System.Threading.ThreadPoolBoundHandleOverlapped
    -> 0000019B67A09C08 System.IO.FileSystemWatcher+AsyncReadState
    -> 0000019B67A09C68 System.WeakReference`1[[System.IO.FileSystemWatcher, System.IO.FileSystem.Watcher]]

@davidfowl These are the files, I ordered it by count.

After100Cycles.txt
Initial.txt

[Tratcher]

Maybe related: #3564. Unfortunately I can't find where that issue ended up.

[davidfowl]

I'll take a look

[davidfowl]

@Leandro-Albano Are you using IIS express or Kestrel?

[Leandro-Albano]

I'm running on Kestrel, on IIS Express I just tried and it seems to not work, the restart never happens because an exception is thrown
The operation was canceled. Exception thrown: 'System.OperationCanceledException' in System.Private.CoreLib.dll. I'll dig into it later today.

[davidfowl]

Yea, we have a leak here. I'm gonna fix it 😄.

[Tratcher]

I'd be surprised if IIS in-proc could be restarted like this, it's too tangled up in the IIS state.

[davidfowl]

True, IIS would need to unwind to native code.

[Tratcher]

@davidfowl #31170 addresses DiagnosticListener, but what about the FileSystemWatcher?

[davidfowl]

I have another PR in runtime coming soon

[davidfowl]

Fixed

[Leandro-Albano]

Awesome job guys, thanks a lot!

[davidfowl]

No thank you for finding that bug. It's been there for ages 🤣