Memory Leak, Increasing CPU usage

[bdrupieski]

This is an awesome library. Thanks for building this.

I dropped this into two .NET Core 2.2 services running in Kubernetes yesterday morning, setting it up to run all of the collectors like this:

DotNetRuntimeStatsBuilder.Customize()
    .WithContentionStats()
    .WithJitStats()
    .WithThreadPoolSchedulingStats()
    .WithThreadPoolStats()
    .WithGcStats()
    .StartCollecting();

Throughout the day I saw memory and CPU usage kept climbing. It looks like there's a memory leak somewhere, and something is causing CPU usage to increase over time.

I already have a metric derived from Process.GetCurrentProcess().WorkingSet64. This is what that metric did yesterday:

The green box shows memory usage when I had all of this library's collectors running. This is for one of the two services, and there are three instances of each, which is why there are three lines on the graph. Each line is Process.GetCurrentProcess().WorkingSet64 over time for that instance. Each time the colors change is from a deployment when the pod names change; the query I'm using for that chart treats them as a completely different metric name at that point.

Here's a graph showing the summed rate of Process.GetCurrentProcess().PrivilegedProcessorTime.TotalSeconds and Process.GetCurrentProcess().UserProcessorTime.TotalSeconds for all instances of each of the two services over the past 2 days:

Sorry for not including the legend -- it has names I don't want to share. The yellow and green lines on the bottom are privileged processor time. The other two are user processor time. One of them is so spiky because it's running a pretty intense scheduled job every 20 minutes. The other is only responding to HTTP requests.

I turned everything off except the thread pool scheduling stats last night. The most recent parts of the above charts are from only running this:

DotNetRuntimeStatsBuilder.Customize()
    .WithThreadPoolSchedulingStats()
    .StartCollecting();

If there's a problem, then it's not with the thread pool scheduling stats.

I'll add the others back one at a time to try to find where the problem is. I'll report back to this issue with my findings.

Thanks again for this library. I didn't know about the CLR events this library records. I'm thankful you wrote this both to learn about them and also to get insight I didn't know was so readily available.

[djluck]

Hey @bdrupieski, thanks for the report, I'll take a look into this over the next week at some point. This library makes use of a number of internal caches and I suspect that these aren't being evicted correctly, leading to higher memory consumption. I also suspect that the increased CPU use could be due to more frequent/ aggressive GC activity- if you could provide a screenshot of the number of GC collections for the impacted time period, that would help confirm this theory.

[bdrupieski]

Here's the past 14 days of the garbage collection rate obtained from calling GC.CollectionCount:

A little bit higher but not too far outside the norm.

CPU and memory remain stable with only ThreadPoolSchedulingStatsCollector. I tried adding ThreadPoolStatsCollector back in but it caused the same problem. I removed that one then tried it for a while with ContentionStatsCollector and it had the same problem, though CPU usage and memory didn't climb so quickly.

Here's a graph showing this for CPU usage from the past 4 days:

[djluck]

@bdrupieski I believe I've fixed the issue, I discovered that EventPairTimer wasn't removing items from it's cache.

I've pushed v2.0.9-beta and v3.0.9-beta to nuget, hopefully this should fix the issue.

[bdrupieski]

Thanks for digging into this and for the quick turnaround. I'll give this a try. I'll turn them all back on and see what happens. I'll report back here with what I find.

[bdrupieski]

I upgraded to v3.0.9-beta and tried to turn all the collectors back on. It. seems to still be happening

Here's memory usage. The green box is when they were all on:

CPU:

I want to try to dig into this myself with a CPU or memory profiler some weekend to figure out what's going on here. Or, to set up remote debugging/profiling to peek into what it's doing exactly when running in Kubernetes and not only locally. I'll try to get to this over the next few days (maybe weeks...).

[djluck]

Hmm interesting. Let me know what you find out- in the meantime, information around the following might help us understand what's going on:

• A graph of the .NET memory generation sizes and how they grow in the affected period
• Are there any memory limits set on the k8s deployment?
• A core dump of the processes memory

[djluck]

So I'm reasonably confident that there's no memory leak in the strictest sense- cached items are being cleaned up correctly.
However, there is an issue with cache growth. Internally, I use ConcurrentDictionary to track pairs of events. If there are thousands. tens of thousands of events being generated a second (which can happen when using the thread pool/ GC stats collectors), the ConcurrentDictionarys have to grow and because the dictionaries grow at an exponential rate, memory consumption can grow without the chance of the memory being reclaimed (ConcurrentDictionary will never shrink unless it's collected by the GC).

I think the solution might be to offer a configurable sampling ratio. This will allow a certain percentage of events to be discarded and reduce cache storage requirements.

[bdrupieski]

Here's sum(dotnet_gc_heap_size_bytes{service="name-of-one-of-the-services"} / 1024 / 1024) by (gc_generation) for the short period I was collecting dotnet_gc_heap_size_bytes recently:

Yes, there are memory limits. This is what I have:

resources:
  limits:
    cpu: 1.0
    memory: 1526Mi
  requests:
    cpu: 0.25
    memory: 1024Mi

I'll look into getting a dump.

[djluck]

@bdrupieski I've pushed a new version into nuget- 3.1.0-beta. Give it a whirl, hopefully it should fix those memory consumption issues.

[djluck]

@bdrupieski, I've also included some optional debugging metrics- you can enable these with when you set up the collectors:

DotNetRuntimeStatsBuilder.Customize()
.WithDebuggingMetrics(true)
...
.StartCollecting()

[thirus]

I'm still seeing a very small memory leak, only the process working set grows, while the GC heap is stable. App has with very little to no load (http requests apart from health and metrics).
The app is running in kubernetes with memory limit set to 512Mb.
Prometheus scrap is set at 10s.

Docker base image is mcr.microsoft.com/dotnet/core/aspnet:2.2:latest
prometheus-net.DotNetRuntime 3.1.1-beta
GC Mode: Workstation (forcibly set in csproj, Server GC does not work)

App Memory Working Set:

App Only Managed Heap size:

This seems to be related to CoreCLR 2.2 issue https://github.com/dotnet/coreclr/issues/23562

I'm trying running the app with environment variable COMPlus_EventPipeCircularMB=128 and keeping all the above same, Will update in few days.