OData Client reportedly cause excessive memory usage after .NET 6 upgrade

[habbes]

A customer reported that after upgrading to .NET 6 from .NET Core 3.1 and updating OData Client to 7.10.0, their performance and load testing reveal excessive memory usage and they have attributed it to OData client. Here are parts of the report:

Performance testing has revealed a memory issue: high private bytes being consumed in the App Service during load testing. You can see that before the migration to .netcore6 and the update to OData, the memory was stable; after, we see the same application using massive amounts of memory. Analysis of memory dumps taken during the testing points to OData as the culprit as identified in the analysis below.

-Overall memory consumption is high:

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                                    799     7de6`e6827000 ( 125.902 TB)           98.36%
Other                                   210      200`002e0000 (   2.000 TB)  95.33%    1.56%
<unknown>                              3253       18`7dbe4000 (  97.965 GB)   4.56%    0.07%
Stack                                   577        0`75990000 (   1.837 GB)   0.09%    0.00%
Image                                  3545        0`15b00000 ( 347.000 MB)   0.02%    0.00%
Heap                                    803        0`102f4000 ( 258.953 MB)   0.01%    0.00%
TEB                                     192        0`00180000 (   1.500 MB)   0.00%    0.00%
PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%
--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_MAPPED                              228      200`009a7000 (   2.000 TB)  95.33%    1.56%
MEM_PRIVATE                            4806       19`03092000 ( 100.047 GB)   4.66%    0.08%
MEM_IMAGE                              3545        0`15b00000 ( 347.000 MB)   0.02%    0.00%
--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                801     7de6`e6ab7000 ( 125.902 TB)           98.36%
MEM_RESERVE                            1204      217`4a0ee000 (   2.091 TB)  99.66%    1.63%
MEM_COMMIT                             7375        1`cf44b000 (   7.239 GB)   0.34%    0.01%

97.965GB of virtualalloc, out of which, GC is only 6GB
GC Committed Heap Size: Size: 0x16b85f000 (6,098,907,136) bytes.

-Machine-wide CPU is very high:

0:000> !threadpool
logStart: 31
logSize: 200
CPU utilization: 100% Worker Thread: Total: 83 Running: 42 Idle: 41 MaxLimit: 32767 MinLimit: 300
Work Request in Queue: 0
--------------------------------------
Number of Timers: 4
--------------------------------------
 
-Most busy threads in the user-mode:
0:000> !runaway
 User Mode Time
  Thread       Time
   38:d0       0 days 0:37:18.765 <=GC
   41:2e80     0 days 0:23:07.671 <=GC
   40:198c     0 days 0:15:45.140 <=GC
   39:2560     0 days 0:15:40.515 <=GC
   58:158c     0 days 0:09:32.250 <=GC
   61:25cc     0 days 0:05:28.218 <=GC
   60:bb4      0 days 0:03:31.187 <=GC
   59:ea0      0 days 0:03:30.031 <=GC

-To find out why long-running threads are busy with Garbage Collection, we will need to look
at the managed heap to find out which objects are accumulating faster causing GC to run frequently. As GC runs frequently, which is an expensive cpu-intensive operation, will shoot-up CPU consumption.

-Here is the most offender list:

As seen clearly, Microsoft.OData.* objects related to Entity Framework are flooding the managed heap.

Here is a partial output of the gcroot

0:000> !gcroot 000002001c910348
Thread 1a54:
    00000040FC51E950 00007FFF32E6EB24 System.Runtime.CompilerServices.ConditionalWeakTable`2+Container[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]].FindEntry(System.__Canon, System.Object ByRef) [/_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/ConditionalWeakTable.cs @ 525]
        rsi:
            ->  000001FC1B5354B8 System.Runtime.CompilerServices.ConditionalWeakTable`2+Container[[Microsoft.OData.ODataAnnotatable, Microsoft.OData.Core],[Microsoft.OData.Client.Materialization.ODataItemExtensions+MaterializerPropertyValue, Microsoft.OData.Client]]
            ->  000002001C910348 System.Runtime.CompilerServices.ConditionalWeakTable`2+Entry[[Microsoft.OData.ODataAnnotatable, Microsoft.OData.Core],[Microsoft.OData.Client.Materialization.ODataItemExtensions+MaterializerPropertyValue, Microsoft.OData.Client]][]

-We also see reachable queue is not cleared. You are explicitly coding destructor/Finalize(), instead Developers should be using Dispose pattern implementing IDisposable interface. If there are no unmanaged objects (that you opened-up explicitly in your code) to clean, then DO NOT implement destructor/Finalize().If there are unmanaged objects to clean, then use the IDisposable (Dispose pattern). It will let the framework clean-up your managed objects while executing your custom code for cleaning/closing any unmanaged object.

Assemblies affected

Which assemblies and versions are known to be affected e.g. OData .Net lib 7.x

Reproduce steps

The simplest set of steps to reproduce the issue. If possible, reference a commit that demonstrates the issue.

Expected result

What would happen if there wasn't a bug.

Actual result

What is actually happening.

Additional detail

Optional, details of the root cause if known. Delete this section if you have no additional details to add.

[habbes]

Additional information from the client:
OData Client was also updated from 7,7.3 to 7.11.0 (to take advantage of the feature allowing the customer to customize the HttpClientHandler), it was also updated to 7.12.0 and 7.12.2.

[habbes]

Before closing this task, let me share some updates. While replacing the ConditionalWeakTable with Dictionary-based request-scoped caches improved and stabilized memory use significantly, the memory usage reported in .NET 6 was still greater than that reported in .NET Core 3.1.

After conducting additional research and experiments, I was able to explain this gap by the fact that .NET 6 does not dispose of memory immediately release memory back to the OS after it's been "freed". It can retain memory if it thinks it might need to allocate it again, this is a performance optimization. However, if it detects low memory in the system, then it will release the memory. Since the profiling was done in machine which still had nearly half of the memory still free, .NET GC did not release the memory. But under memory pressure, the "freed" memory would be released.

Here are potentially related issues:

• Resident Set Size on Linux remains much higher than managed memory usage in .NET 5.0 dotnet/runtime#52592
• How to tell how much memory a .NET 6 application is really using? dotnet/runtime#76249

[habbes]

For reference's sake, here's a summary of the experiments I ran to see how .NET 6 and .NET Core 3.1 garbage collectors behave in different memory constrained scenarios.

I ran series of tests simulating memory constraints. The purpose these tests was to understand how test service running OData Client would behave when it’s about to hit the memory ceiling and compare between .NET 6.0 and .NET Core 3.1. So far our best explanation for this was that GC was no under pressure to do a full compacting Gen2 GC or release memory back to the OS because there was sufficient free memory available. The purpose of these tests was to confirm that GC would be more effective at freeing memory if we were closer to the memory limit. I ran the same tests in docker containers with different memory constraints.

In my tests, 6GB was threshold below which application performance and reliability started to degrade, i.e., some requests would fail due to out-of-memory exceptions. This was the case on both .NET 6.0 and .NET Core 3.1. From 6GB and above the application ran successfully consistently. I also noticed slightly better performance in .NET 6 (in terms of total execution time). The GC metrics adjusted to the amount of available memory. For example, when running the tests in containers without memory limits, peak heap size was 5.6GB and committed memory as high 7.8GB. However, when I set the memory limit to 6GB, the peak heap size was 4.1GB and committed memory peaked at 4.4GB with no noticeable drop in performance. I also noticed that the application was more stable when using HttpWebRequest transport mode than HttpClient when memory was more constrained. In such conditions (< 4GB max memory), the container seemed more likely to crash or fail all requests when using HttpClient transport mode.

Based on these results, my conclusion is that high memory usage is likely not to be an issue of great concern in production if your load testing environment is representative of the kind of load you would expect during peak season. I don’t think it would be less capable of handling the load than when using .NET Core 3.1. I would suggesting testing with an even higher load just to understand where the breaking point is and how much the system could comfortably handle. I would suggest that you use HttpWebRequest transport mode for now (unless you test the nightly build and it shows that HttpClient mode is better).

Each test consisted of sending 60 requests using 30 virtual users (using k6 load testing tool) to the test server. The test server was running in a docker container with adjusted memory limit and .NET version. The test server used OData Client to fetch data from a sample OData service. The OData service exposed a sample Customers entity set endpoint that return 20,000 customers which amounted to about 1.7mb of JSON. This was meant to simulate some of the large requests that we found in the dumps EY shared with us.

.NET Core version	HttpRequestTransportMode	Memory Limit	Peak Allocated Heap Size	Peak Heap Committed Memory	Duration	Successful Requests	Remarks
3.1	HttpWebRequest	N/A	6.4	N/A	1m15s	60/60
3.1	HttpClient	N/A	5.8	N/A	1m14s	60/60
3.1	HttpWebRequest	2GB	1.5	N/A	1m56s	0/60	Container crashed altogether after running out of memory.
3.1	HttpClient	2GB	1.5	N/A	1m50s	7/53 (11%)	Requests failed due to OOM exceptions
3.1	HttpWebRequest	4GB	3.0	N/A	1m56	25/60 (41%)
3.1	HttpClient	4GB	3.0	N/A	1m58	24/60 (40%)
3.1	HttpWebRequest	5GB	3.7	N/A	1m59	29 (48%)
3.1	HttpClient	5GB	3.8	N/A	1m33	34 (56%)
3.1	HttpWebRequest	6GB	4.7	N/A	1m20s	60/60
3.1	HttpClient	6GB	4.3	N/A	1m22s	60/60
6.0	HttpWebRequest	N/A	5.9	7.8	1m18	60/60
6.0	HttpClient	N/A	5.6	7.6	1m09s	60/60
6.0	HttpWebRequest	6GB	4.1	4.4	1m06s	60/60
6.0	HttpClient	6GB	4.2	4.4	1m04s	60/60
6.0	HttpWebRequest	5GB	3.6	3.8	1m27	43/60 (71%)
6.0	HttpClient	5GB	3.4	3.7	54.3s	51/60 (85%)	In one test run, the container crashed due to running out of memory. But it was relatively stabler in most runs and managed to reach 100% request success rate in at least 2 test runs.
6.0	HttpWebRequest	4GB	2.5	2.9	1m30	22/60 (36%)
6.0	HttpClient	4GB	2.8	3.0	1m18	0/60	Container crashed in many  cases. In some cases managed to rich 40% and 78% success rate.