Large Gen0 GC size after hours of Runtime

Question

I am running .NET 4.8 x64 (4.8.4300.0) where after a ca. 14h stress test the GC times are much higher than at the start. With PerfView I can see that the size of Gen0 Heap has grown a lot. Are there known issues with Gen0 Heap size and .NET 4.8?

Iteration 10

• Total CPU Time: 136,245 msec
• Total GC CPU Time: 7,171 msec
• Total Allocs : 10,023.772 MB
• GC CPU MSec/MB Alloc : 0.715 MSec/MB
• Total GC Pause: 8,361.5 msec
• % Time paused for Garbage Collection: 5.5%
• % CPU Time spent Garbage Collecting: 5.3%
• Max GC Heap Size: 460.052 MB
• Peak Process Working Set: 1,166.688 MB
• Peak Virtual Memory Usage: 7,314.285 MB

Iteration 300

• Total CPU Time: 141,466 msec
• Total GC CPU Time: 14,364 msec
• Total Allocs : 10,235.755 MB
• GC CPU MSec/MB Alloc : 1.403 MSec/MB
• Total GC Pause: 22,767.4 msec
• % Time paused for Garbage Collection: 13.6%
• % CPU Time spent Garbage Collecting: 10.2%
• Max GC Heap Size: 887.517 MB
• Peak Process Working Set: 1,916.793 MB
• Peak Virtual Memory Usage: 8,047.583 MB

When I plot from ETW the CPU consumption of GC, Background GC and Induced GC for various iteration counts I find a clear correlation with increased GC costs and iteration count.

The strange thing is that the managed heap has not really become much larger. This does not look like a managed memory leak (ok it leaks a bit but not that much) but some GC issue or did I look at the data in the wrong way?

Update 1 Here is the call stack of the GC which seems to be pretty expensive:

Stack Tag, Stack, Weight (in view) (ms)
4, ,   Background GC, , 245.131400
5, , , [Root], 245.131400
6, , ,   ntdll.dll!RtlUserThreadStart, 245.131400
7, , ,   kernel32.dll!BaseThreadInitThunk, 245.131400
8, , ,   clr.dll!Thread::intermediateThreadProc, 245.131400
9, , ,   clr.dll!<lambda_29e7ea55b6ca6bda8a02df3a0a3e58b1>::operator(), 245.131400
10, , ,   clr.dll!WKS::gc_heap::bgc_thread_function, 245.131400
11, , ,   clr.dll!WKS::gc_heap::gc1, 245.131400
12, , ,   clr.dll!WKS::gc_heap::background_mark_phase, 245.131400
13, , ,   |- clr.dll!GCScan::GcScanHandles, 203.131000
14, , ,   |    clr.dll!Ref_TraceNormalRoots, 203.131000
15, , ,   |    clr.dll!HndScanHandlesForGC, 203.131000
16, , ,   |    clr.dll!TableScanHandles, 203.131000
17, , ,   |    clr.dll!BlockScanBlocksWithoutUserData, 203.131000
18, , ,   |    clr.dll!ScanConsecutiveHandlesWithoutUserData, 203.131000
19, , ,   |    |- clr.dll!PromoteRefCounted, 202.131100
20, , ,   |    |    |- clr.dll!WKS::gc_heap::background_promote, 196.131800
21, , ,   |    |    |    clr.dll!WKS::gc_heap::background_mark_simple, 196.131800
22, , ,   |    |    |    clr.dll!WKS::gc_heap::background_mark_simple1, 196.131800
23, , ,   |    |    |    |- clr.dll!WKS::gc_heap::background_mark_simple1<itself>, 186.138400

Not sure which objects can make that so expensive. But it looks CPU dominated. This is one Gen2 GC which did take over 250ms to complete

The Induced Gen2 GCs seem to originate from Background GC

Answer 1

After taking dumps I have found many RefCounted objects namely MS.Internal.Automation.ValueProviderWrapper which keep a lot UI objects alive via UI Automation. I think refcounting works which means that the other process which drives the UI is leaking UI Automation objects. At least the increased GC costs can be explained now.

MemAnalyzer has helped also a lot: https://github.com/Alois-xx/MemAnalyzer

to be sure to look at the right things. PerfView is pretty bad at counting objects due to its stack sampling approach. With Memanalyzer and you can gather exact numbers and diffs.

With

C:\dumps>for %i in (*.dmp) do memanalyzer -f MemoryDump_5.dmp -f2 %i -o Diff_5_%i.csv

If I then add a column of the form = ObjectDiff/IterationDiff I can calculate the leakage rate per iteration for different dumps. If we leak one object per iteration I just need to search for objects around 1 or a multiple of it to find leaks which are related per iteration which makes it much easier to reason about root causes.