Asp.net Core not Collecting Garbage

[sebastienros]

Copied from #1976

@sinapis commented on Dec 19, 2017

Hi,

I have the same issue with ASP.NET Core 2. I've took a memory dump and tried analyzing. From what I see the problem is exactly as the OP said. My application starts with allocation about 75 MB, and very quickly it goes all the way to ~750MB, out of it 608MB is "Unused memory allocated to .NET".

First snapshot at app start:

Second snapshot after 3 minutes and 100 requests:

@sebastienros commented on Apr 5

• We only measure this on 2.1, I will look into adding the same thing for 2.0
• All comments seem to be related to to the LOH issue that was mentioned, which should be taken into account in the application and pool large arrays as much as possible

@sinapis commented on Apr 8

@sebastienros, several questions:

1. I used Ants profiler to measure memory usage, according to it, no LOH fragmentation was detected. Can you advise how can I verify if my application suffers from LOH fragmentation issues?
2. What are the results on .net core 2.1? Is the issue resolved because Kestrel is using Span?
3. What if we can't pool arrays - can you provide a workaround? Should we use GCSettings.LargeObjectHeapCompactionMode.CompactOnce?

@davidfowl commented on Apr 8

What are the results on .net core 2.1? Is the issue resolved because Kestrel is using Span?

We personally haven't seen any evidence that the issue is in Kestrel. It still looks like an application problem.

What if we can't pool arrays - can you provide a workaround? Should we use GCSettings.LargeObjectHeapCompactionMode.CompactOnce?

@sebastienros commented on Apr 10

@sinapis
Would any of you be able to share an app that shows the issue? If I could repro it we would be able to find the reason, or at least remove some code piece by piece and isolate a minimal repro.

@sinapis commented on Apr 10

@sebastienros I can't share the app, but I can share the session from PerfView session + memory dump.
Some description: I have a ASP.NET Core 2 Web API, I've created a load test of 200 users all sending the same request over 10 seconds. Overall 775 requests were processed.

This app jumped to almost 1 GB memory usage in task manager and stayed like that. Looking at the dump I can count about 18 MB:

So the questions is where did almost 1 GB go?

@sebastienros commented on Apr 10

@sinapis Thanks

The behavior you are describing is not unexpected, the GC will allocated some memory as necessary on the peak load, and just release it over time. It's the GC Server mode, and usually wait for idle periods to release it and not affect your app perf. The amount of memory it will reserve depends of the total memory available on the system.

We would definitely see an issue if it kept increasing. I assume that if you don't send anymore requests and let your app run you will see the memory usage going down.

Could you run the same thing until it consumes most of your system memory? Or at least long enough with the same load that it will show it growing continuously? I will still get a look at your current dumps.

@sebastienros commented on Apr 10

Also can you take dumps during and at the end of the jobs, so we can see the detals.

@Maoni0 commented on Apr 11

@sinapis I looked at your ETW trace. it is puzzling to me - you survived very little in the last induced gen2 GC yet we still chose to keep that much memory committed. your application seems edge case (you mostly just did only background GCs due to LOH allocations) - I wonder if we have some accounting errors there (another possibility is errors in the numbers reported but if you already verified that you have that much committed that's a smaller possibility). if you could repro with something you can share with me, that'd be fantastic; otherwise if it's possible to run your app with some logging from GC (I can give you a commit that does that) that'd be helpful too.

@sinapis commented on Apr 11

@Maoni0 please share how should I enable GC logging
If there is some other data you would like me to provide in order to disprove accounting error please let me know what should I provide you with and how (maybe tell perfview to collect more data?)
I'll try creating a minimum repro, but not sure I'll succeed since I don't know where the problem is.

@sebastienros hopefully I will provide another dump with more memory consumption today

[sebastienros]

@sinapis

Are you still waiting from us to make progress on this issue?

[Gorthog]

Hi,

That project was abandoned but it's very important for us to get to the bottom of this issue. I could use the info how to record more info on GC.

Also, please describe what exactly I can provide that will help got to the bottom of this issue.

[Maoni0]

@sinapis are you trying to find out the issue you described above or just interested in recording more info in general? for the former, are you in a position to build a private coreclr.dll and use that in your project that's showing the symptom you described? if so I can just give you a commit with proper logging enabled.

[Gorthog]

@Maoni0 Yes, I can build a private coreclr.dll and use it. If there is are additional logging you would like me to add, I'd be more than happy to do so. In general, tell me what you need. I'll do whatever I can.

[NickCraver]

Environment

We are currently on .NET Core, version 2.1.300, but are installing 2.2 preview 3 for testing likely this week. I'll re-visit this issue then to confirm or show changes.

Details

We are seeing this at Stack Overflow with our canary .NET Core web socket server as well. We are observing 2 behaviors:

1. GC does not appear to be running on it's own. We are seeing Gen 0 grow to gigabytes (at which point we have to kill it).
2. When GC is forced to run, overall process memory is not freed.

Here's a before and after of a forced all-generations GC run:

Before	After

Note that gen 0 is cleared, the long-lived websocket object trees (expected) are moved to gen 2, and overall memory usage drops to 530MB. However, overall process memory was at 2.8GB and remains at 2.8GB. Even though only 530MB is used internally.

We currently have a timer running inside the application forcing GC to get by for other testing, but that's not a great idea and really shouldn't be necessary. I currently consider this a blocker to deploying Stack Overflow on .NET Core. What can we do to help? We have memory dumps and can readily do analysis and testing to assist.

[Tratcher]

How's the fragmentation? That can cause symptoms like this when there's lots of pinned buffers.

[sebastienros]

How much memory is on the system?

[davidfowl]

There should be no new pinned buffers when using ASP.NET Core. The only pinned buffers are the ones Kestrel uses.

[sebastienros]

What we'll need:

• Something we can repro consistently, and ideally locally
• Memory dumps
• Perfview traces under load

[NickCraver]

@Tratcher Attaching !dumpheap -stat and !eeheap-gc here: SocketServerDbg.txt (happy to do any other breakdowns as well) - this is on the 530MB dump (assuming you wanted highest fragmentation).

@sebastienros Specs:

• 24 Cores, 48 logical processors
• 64GB of RAM (43.3GB in use)

I don't think we can provide memory dumps here as they contain user cookies due to the nature of the application and that's a security issue, but we're more than happy to assist as best we can. On the perfview front: send instructions and happy to help.

[benaadams]

How's the fragmentation? That can cause symptoms like this when there's lots of pinned buffers.

Looking at the dump doesn't look huge?

Total 5432168 objects
Fragmented blocks larger than 0.5 MB:
           Addr     Size      Followed by
00000218476b92e8    1.2MB 00000218477e12d8 System.Byte[]

[sebastienros]

GC does not appear to be running on it's own. We are seeing Gen 0 grow to gigabytes (at which point we have to kill it).

When you say "grow to gigabytes", this is not something that is unexpected. I understand you are aware that the Server GC will be triggered by memory pressure. If there is no pressure (you have 64GB) it doesn't have to be triggered. So it's all about how much available memory was left when you decided to kill it. Are these numbers the ones you shared before or were they higher that that?

Quoting the documentation:

Garbage collection occurs when one of the following conditions is true:

• The system has low physical memory. This is detected by either the low memory notification from the OS or low memory indicated by the host.
• The memory that is used by allocated objects on the managed heap surpasses an acceptable threshold. This threshold is continuously adjusted as the process runs.

These explanations are very fuzzy: "acceptable threshold". It doesn't tell what is acceptable or not, and you might have other acceptance thresholds ;)

When GC is forced to run, overall process memory is not freed.

Same. I assume that's an expected behavior, though it doesn't mean it's what should have happened, but nothing tells me it shouldn't behave this way from the data you shared.

@Maoni0 is this is an expected behavior based on the numbers that were provided?

I have never tried to run an ASP.NET app and experience how the GC behaves with such an amount of RAM to see what these thresholds look like.

[NickCraver]

Are these numbers the ones you shared before or were they higher that that?

Oh no, it just takes a while to grow (due to the long-lived nature of sockets, connections ramp up slowly). It grows well beyond what's here.
I've let it run since posting ~4 hours ago and I just took another dump. It's at 5GB from the Windows view. Here's the breakdown:

I understand being lazy and using available memory...but that's way beyond anything I've ever seen in Gen 0.

With every .NET full framework application we have today: GC runs as expected, and memory is freed instantaneously or very shortly after a run. This is critical behavior for a shared web tier. If every app only runs GC when there's memory pressure, you're lighting 8 sticks of dynamite at once all to go off at the same time and pegging CPU when they do get a pressure signal. I'm really hoping this is a GC bug, because if it's expected behavior we have legitimate concerns and blockers with such behavior.

Standing by to run whatever diagnostics will help. And we're more than happy to run a custom build with better logging, etc. Whatever we can do - this is my highest priority to fix. I'm happy to force a GC and get numbers, but will await feedback here before doing so - lest we lose data you'd like to see.