Gen2 collection not always collecting dead objects?

Question

By monitoring the CLR #Bytes in all Heaps performance counter of a brand new .NET 4.5 server application over the last few days, I can notice a pattern that makes me think that Gen2 collection is not always collecting dead objects, but I am having trouble understanding what exactly is going on.

Server application is running in .NET Framework 4.5.1 using Server GC / Background.

This is a console application hosted as a Windows Service (with the help of Topshelf framework)

The server application is processing messages, and the throughput is somehow pretty constant for now.

What I can see looking at the graph of CLR #Bytes in all Heaps is that the memory started arround 18MB then growing up to 35MB on approx 20-24 hours (with between 20-30 Gen2 collections during that time frame), and then all of a sudden dropping back to nominal value of 18MB, then growing again up to ~35MB over 20-24 hours and dropping back to 18MB, and so on (I can see the pattern repeating over the last 6 days the app is now running) ... The growing of memory is not linear, it takes approx 5 hours to grow by 10MB and then 15-17 hours for the remaining 10 MB or so.

Thing is that I can see by looking at perfmon counters for #Gen0/#Gen1/#Gen2 collections that a bunch of Gen2 collections are going on during the 20-24 hours period (maybe arround 30) and none of them makes the memory drop back to nominal 18MB. However, what is strange is by using an external tool to force a GC (Perfview in my case), then I can see #Induced GC going up by 1 (GC.Collect was called so this is normal) and immediately the memory is going back to nominal 18MB.

Which leads me into thinking that either the perfmon counter for #Gen2 collections is not right and only a single Gen2 collection happens after 20-22hours or so (meeehhh I really don't think so) or that the Gen2 collection does not always collect dead objects (seems more plausible) ... but in that case why would forcing a GC via GC.Collect do the trick, what would be the difference between explicitely calling into GC.Collect, v.s automatic triggered collections during the lifetime of the application.

I am sure there is a very good explanation but from the different source of documentation I have found about GC -too few :(- a Gen2 collection does collect dead objects in any case. So maybe docs are not up to date or I have misread ... Any explanation is welcome. Thanks !

EDIT : Please see this screenshot of the #Bytes in all heaps graph over 4 days

_{(Click for larger view)}

this is easier than trying to graph things in your head. What you can see on the graph is what I said above... memory increasing over 20-24hours (and 20-30 Gen2 collections during that time frame) until reaching ~35MB then dropping all of a sudden. You will note at the end of the graph, the induced GC I triggered via an external tool, immediately dropping back memory to nominal.

EDIT #2 : I made a lot of cleaning in the code, mainly regarding finalizers. I had a lot of classes that were holding reference to disposable types, so I had to implement IDisposable on these types. However I was misguided by some articles into implementing the Diposable pattern with a Finalizer in any case. After reading some MSDN documentation I came to understand that a finalizer was only required when the type was holding native resources itself (and still in that case this could be avoided with SafeHandle). So I removed all finalizers from all these types. There were some other modications in the code, but mainly business logic, nothing ".NET framework" related. Now the graph is very different, this is a flat line arround 20MB for days now ... exactly what I was expecting to see ! So the problem is now fixed, however I still have no idea what was the problem due to ... It seems like it might have been related to finalizers but still does not explain what I was noticing, even if we weren't calling Dispose(true) -suppressing finalizer-, the finalizer thread is supposed to kick in between collection and not every 20-24 hours ?! Considering we have now moved away from the problem, it will take time to come back to the "buggy" version and reproduce it again. I may try to do it some time though and go to the bottom of it.

EDIT: Added Gen2 collection graph _{(Click for larger view)}

Answer 1

From

http://msdn.microsoft.com/en-us/library/ee787088%28v=VS.110%29.aspx#workstation_and_server_garbage_collection

Conditions for a garbage collection

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

• The system has low physical memory.

• 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.

• The GC.Collect method is called. In almost all cases, you do not have to call this method, because the garbage collector runs continuously. This method is primarily used for unique situations and testing.

It seems that you are hitting the 2nd one and 35 is the threshold. You should be able to configure the threshold to something else if 35 is to large.

---

There isn't anything special about gen2 collections that would cause them to deviate from these rules. (cf https://stackoverflow.com/a/8582251/215752)

Answer 2

Are any of your objects "large" objects? there's a separate "large object heap" which has different rules

Large Object Heap Fragmentation

It was improved in 4.5.1, though:

http://blogs.msdn.com/b/dotnet/archive/2011/10/04/large-object-heap-improvements-in-net-4-5.aspx

Answer 3

This could easily be explained if gcTrimCommitOnLowMemory is enabled. Normally, the GC keeps some extra memory allocated to the process. However, when the memory reaches a certain threshold, the GC will then "trim" the extra memory.

From the docs:

When the gcTrimCommitOnLowMemory setting is enabled, the garbage collector evaluates the system memory load and enters a trimming mode when the load reaches 90%. It maintains the trimming mode until the load drops under 85%.

This could easily explain your scenario - the memory reserves are being kept (and used) until your application reaches a certain point, which seems to be once every 20-24 hours, at which point the 90% load is detected, and the memory is trimmed to its minimum requirements (the 18mb).

Answer 4

Reading your first version I would say that is a normal behavior.

...but in that case why would forcing a GC via GC.Collect do the trick, what would be the difference between explicitely calling into GC.Collect, v.s automatic triggered collections during the lifetime of the application.

There is two type of collections, a full collection and a partial collection. What the automatic triggered does is a partial collection, but when calling GC.Collect it will do a full collection.

Meanwhile, I might have the reason of it now that you told us that you were using finalizer on all of your objects. If for any reason one of those objects were promoted to #2 Gen, the finalizer would only run when doing a #2 Gen collection.

The following example will demonstrate what I just said.

public class ClassWithFinalizer 
{
    ~ClassWithFinalizer()
    {
        Console.WriteLine("hello from finalizer");
        //do nothing
    }
}

static void Main(string[] args)
{
    ClassWithFinalizer a = new ClassWithFinalizer();
    Console.WriteLine("Class a is on #{0} generation", GC.GetGeneration(a));
    GC.Collect();
    Console.WriteLine("Class a is on #{0} generation", GC.GetGeneration(a));
    GC.Collect();
    Console.WriteLine("Class a is on #{0} generation", GC.GetGeneration(a));

    a = null;

    Console.WriteLine("Collecting 0 Gen");
    GC.Collect(0);
    GC.WaitForPendingFinalizers();

    Console.WriteLine("Collecting 0 and 1 Gen");
    GC.Collect(1);
    GC.WaitForPendingFinalizers();

    Console.WriteLine("Collecting 0, 1 and 2 Gen");
    GC.Collect(2);
    GC.WaitForPendingFinalizers();

    Console.Read();
}

The output will be:

Class a is on #0 generation
Class a is on #1 generation
Class a is on #2 generation
Collecting 0 Gen
Collecting 0 and 1 Gen
Collecting 0, 1 and 2 Gen
hello from finalizer

As you can see, only when doing a collection on the generation where the object is, the memory of the objects with finalizer will be reclaimed.

Answer 5

Just figure I'll throw in my 2 cents here. I'm not an expert at this but maybe this might help your investigation.

If you're using a 64-bit platform try adding this to your .config file. I read that that can be an issue.

<configuration>
    <runtime>
        <gcAllowVeryLargeObjects enabled="true" />
    </runtime>
</configuration>

The only other thing I would point out is that you could prove your hypothesis by troubleshooting from the inside if you are in control of the source code.

Calling something along the lines of this your app's main memory consuming class, and setting it to run on timed intervals, could shed some light onto what's really going on.

private void LogGCState() {
    int gen = GC.GetGeneration(this);

    //------------------------------------------
    // Comment out the GC.GetTotalMemory(true) line to see what's happening 
    // without any interference
    //------------------------------------------
    StringBuilder sb = new StringBuilder();
    sb.Append(DateTime.Now.ToString("G")).Append('\t');
    sb.Append("MaxGens: ").Append(GC.MaxGeneration).Append('\t');
    sb.Append("CurGen: ").Append(gen).Append('\t');
    sb.Append("CurGenCount: ").Append(GC.CollectionCount(gen)).Append('\t');
    sb.Append("TotalMemory: ").Append(GC.GetTotalMemory(false)).Append('\t');
    sb.Append("AfterCollect: ").Append(GC.GetTotalMemory(true)).Append("\r\n");

    File.AppendAllText(@"C:\GCLog.txt", sb.ToString());

}

Also there is a pretty good article here on using the GC.RegisterForFullGCNotification method. Obviously this would enable you to also include the time span of a full collection so that you could possibly tune performance and collection frequency to your specific needs. This method also let's you specify a heap threshold to to trigger notifications (or collections?).

There's also probably a way to set that in the apps .config file but I haven't looked. For the most part 35MB is a pretty small footprint for a Server Application these days. Heck, my web browser makes it up to 300-400MB sometimes :) So, the Framework might just see 35MB as a good default point to free up memory.

Anyhow, I can tell by the thoughtfulness of your question that I'm probably just pointing out the obvious. But, it feels worth mentioning. I wish you luck!.

On a funny note

At the top of this post I had originally written "if (you're using a 64-bit platform)". That made me crack up. Take care!

Answer 6

I have exactly the same situation in my WPF application. No finalizers in my code btw. However it seems that ongoing GC actually collects Gen 2 objects. I can see that GC.GetTotalMemory() results reduces up to 150mb after Gen2 collection triggered.

So I'm under impression that Gen2 heap size does not show amount of bytes that is used by live objects. It is rather just a heap size or amount of bytes that is allocated for Gen2 purposes. You may have plenty of free memory there.

Under some conditions (not on each gen 2 collection) this heap size is trimmed. And at this particular moment my application gets a huge performance hit - it may hung up to sevetal seconds. Wondering why...