This article is Part 1 in a 2-Part Series.
- Part 1 - This Article
- Part 2 - The cost of garbage collection. Part 2 - rectification.
Update There is a error in the first version of this code, and the tests are in fact always operating in a situation that almost all object are in generation 2. The answer is in the next post
In the previous post I’ve promised to write how to have differentiate the number of workers in Hangfie, but in the comments Michał asked one interesting question - “Is generation 1 collection more expensive then generation 0 collection?”. Going further how does generation 2 collection fit into it?
I always believed that running GC.Collect is more expensive the deeper we go. So GC.Collect(0) is the least expensive, and GC.Collect(2) is most expensive. This opinion was reinforced by articles I remember reading and general opinion that .NET is optimized for fast young object collection.
But after a moment of thought I came to conclusion that the same/very similar algorithm could be used for every garbage collection generation. I started a conversation with my team at work, and after a while they came to more or less the same conclusion:
We don’t know. And to make matters worse there seem to be articles stating opposite opinions in this topic.
The only thing left was to check.
To check I needed couple of things:
1. Large number of object that can be collected.
I’ve assumed that increasing the number of objects will influence garbage collection time - this is quite logical assumption. One thing to have in mind is that those have to be objects (instances of classes) not structs. Why? Because structs and classes are collected in different ways. Classes are collected by counting references during GC.Collect, and structs, since you can’t have a reference to it, are collected when they loose scope, or during collection of object that contains it. More on this can be read for example here So my class looks like this:
private class MyGCTestClass
{
private readonly string Text;
public MyGCTestClass(string text)
{
Text = text;
}
public MyGCTestClass(MyGCTestClass source)
{
Text = source.Text;
}
}
And generating code looks like this:
private List<MyGCTestClass> GenerateObjects(long count)
{
var ret = new List<MyGCTestClass>();
for (var i = 0; i < count; i++)
{
ret.Add(new MyGCTestClass(Guid.NewGuid().ToString()));
}
return ret;
}
2. A way to trigger garbage collection
Since .NET has two garbage collectors (client and server) and I wanted to measure time impact so using the blocking one (client) was the only logical choice. A quick entry in app/web.config:
<configuration>
<runtime>
<gcServer enabled="false" />
</runtime>
</configuration>
Also GC.Collect has several overloads. The four parameter overload enables to:
- set the collection as blocking
- force garbage collection to actually execute
- force compacting (So not only marking objects for deletion, but also moving the rest together to minimize memory fragmentation ) The call will look like this:
GC.Collect(generationNumber, GCCollectionMode.Forced, true, true);
3. A way to check how many times collection was executed
Because .NET runtime can trigger garbage collection on its own I had to be sure that the only garbage collection was that triggered by me.
This can be done by using GC.RegisterForFullGCNotification, but performance benchmarks like NBench or BenchmarkDotNet have it nicely wrapped. I’ve decided to go with NBench and it’s GcTotalAssertion attribute.
So my test class looked like this:
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using NBench;
namespace Tests
{
public class GCCollection
{
private readonly string[] _messages =
{
"Gen 0 ticks: ",
"Gen 0+1 ticks: ",
"Gen 0+1+2 ticks: "
};
private List<MyGCTestClass> _list;
[PerfSetup]
public void Setup(BenchmarkContext context)
{
_list = GenerateObjects(20*1000*1000);
Console.WriteLine("Objects generated.");
GC.Collect(2, GCCollectionMode.Forced, true,true);/*To be sure everything that can will be collected.*/
}
[PerfBenchmark(Description = "Gen 0 collection", NumberOfIterations = 1, RunMode = RunMode.Iterations,TestMode = TestMode.Test)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen0, MustBe.ExactlyEqualTo, 1d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen1, MustBe.ExactlyEqualTo, 0.0d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen2, MustBe.ExactlyEqualTo, 0.0d)]
public void Gen0Collection()
{
_list = null;
var sw = Stopwatch.StartNew();
RunGCAndCheck(0, sw);/* Run collect for gen 0 - collect everything.*/
}
[PerfBenchmark(Description = "Gen 1 collection", NumberOfIterations = 1, RunMode = RunMode.Iterations,TestMode = TestMode.Test)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen0, MustBe.ExactlyEqualTo, 2.0d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen1, MustBe.ExactlyEqualTo, 1.0d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen2, MustBe.ExactlyEqualTo, 0.0d)]
public void Gen1Collection()
{
var sw = Stopwatch.StartNew();
RunGCAndCheck(0, sw);/* Can't collect anything. Move it to gen 1.*/
_list = null;
RunGCAndCheck(1, sw);/* Run collect for gen 0 - it is empty. Run gen 1 collection - collect everything.*/
}
[PerfBenchmark(Description = "Gen 2 collection", NumberOfIterations = 1, RunMode = RunMode.Iterations,TestMode = TestMode.Test)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen0, MustBe.ExactlyEqualTo, 3.0d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen1, MustBe.ExactlyEqualTo, 2.0d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen2, MustBe.ExactlyEqualTo, 1.0d)]
public void Gen2Collection()
{
var sw = Stopwatch.StartNew();
RunGCAndCheck(0, sw);/* Can't collect anything. Move it to gen 1.*/
RunGCAndCheck(1, sw);/* Run collect for gen 0 - it is empty. Run gen 1 collection - collect the list elements.*/
_list = null;
RunGCAndCheck(2, sw);/* Run collect for generation 0 - it is empty. Run collect for generation 1 - it is empty. Run collect for generation 2 - collect everything.*/
}
[MethodImpl(MethodImplOptions.AggressiveInlining)]
private void RunGCAndCheck(int generationNumber, Stopwatch sw)
{
sw.Restart();
GC.Collect(generationNumber, GCCollectionMode.Forced, true,true);
Console.WriteLine(_messages[generationNumber] + sw.ElapsedTicks);
}
private List<MyGCTestClass> GenerateObjects(long count)
{
var ret = new List<MyGCTestClass>();
for (var i = 0; i < count; i++)
{
ret.Add(new MyGCTestClass(Guid.NewGuid().ToString()));
}
return ret;
}
private class MyGCTestClass
{
private readonly string Text;
public MyGCTestClass(string text)
{
Text = text;
}
public MyGCTestClass(MyGCTestClass source)
{
Text = source.Text;
}
}
}
}
Some things to point out:
RunGCAndCheckhas[MethodImpl(MethodImplOptions.AggressiveInlining)]to inline the method and thus minimize the chance garbage collection will be called after it exits.Setupwill be called before every test because of thePerfSetupattribute.- Running
GC.Collect(n)will cause garbage collection on all generation up to and with n-th generation.
Running the test in NBench
First thing to note is that NBench requires it’s own runner (it is avilable on nuget). The second is that it runs every test twice as a warm up to minimize for such things like time spend by .NET allocating memory, and JITing the code.
Gen0Collection (objects collected in generation 0 collection):
------------ STARTING Tests.GCCollection+Gen0Collection ----------
Objects generated.
Gen 0 ticks: 21257
Objects generated.
Gen 0 ticks: 42541
--------------- BEGIN WARMUP ---------------
Elapsed: 00:00:00.0171519
TotalCollections [Gen0] - collections: 1,00 ,collections: /s 58,30 , ns / collections: 17 151 979,67
TotalCollections [Gen1] - collections: 0,00 ,collections: /s 0,00 , ns / collections: 17 151 979,67
TotalCollections [Gen2] - collections: 0,00 ,collections: /s 0,00 , ns / collections: 17 151 979,67
--------------- END WARMUP ---------------
Objects generated.
Gen 0 ticks: 47949
--------------- BEGIN RUN ---------------
Elapsed: 00:00:00.0192217
TotalCollections [Gen0] - collections: 1,00 ,collections: /s 52,02 , ns / collections: 19 221 705,61
TotalCollections [Gen1] - collections: 0,00 ,collections: /s 0,00 , ns / collections: 19 221 705,61
TotalCollections [Gen2] - collections: 0,00 ,collections: /s 0,00 , ns / collections: 19 221 705,61
--------------- END RUN ---------------
--------------- RESULTS: Tests.GCCollection+Gen0Collection ---------------
Gen 0 collection
--------------- DATA ---------------
TotalCollections [Gen0]: Max: 1,00 collections, Average: 1,00 collections, Min: 1,00 collections, StdDev: 0,00 collections
TotalCollections [Gen0]: Max / s: 52,02 collections, Average / s: 52,02 collections, Min / s: 52,02 collections, StdDev / s: 0,00 collections
TotalCollections [Gen1]: Max: 0,00 collections, Average: 0,00 collections, Min: 0,00 collections, StdDev: 0,00 collections
TotalCollections [Gen1]: Max / s: 0,00 collections, Average / s: 0,00 collections, Min / s: 0,00 collections, StdDev / s: 0,00 collections
TotalCollections [Gen2]: Max: 0,00 collections, Average: 0,00 collections, Min: 0,00 collections, StdDev: 0,00 collections
TotalCollections [Gen2]: Max / s: 0,00 collections, Average / s: 0,00 collections, Min / s: 0,00 collections, StdDev / s: 0,00 collections
--------------- ASSERTIONS ---------------
[PASS] Expected TotalCollections [Gen0] to must be exactly 1,00 collections; actual value was 1,00 collections.
[PASS] Expected TotalCollections [Gen1] to must be exactly 0,00 collections; actual value was 0,00 collections.
[PASS] Expected TotalCollections [Gen2] to must be exactly 0,00 collections; actual value was 0,00 collections.
------------ FINISHED Tests.GCCollection+Gen0Collection ----------
The test itself is the part after END WARMUP. And according do this run generation 0 collection collecting all the objects lasts 47949 ticks.
Gen1Collection (objects collected in generation 1 collection)
------------ STARTING Tests.GCCollection+Gen1Collection ----------
Objects generated.
Gen 0 ticks: 45994
Gen 0+1 ticks: 546
Objects generated.
Gen 0 ticks: 45196
Gen 0+1 ticks: 522
--------------- BEGIN WARMUP ---------------
Elapsed: 00:00:00.0194638
TotalCollections [Gen0] - collections: 2,00 ,collections: /s 102,75 , ns / collections: 9 731 939,08
TotalCollections [Gen1] - collections: 1,00 ,collections: /s 51,38 , ns / collections: 19 463 878,17
TotalCollections [Gen2] - collections: 0,00 ,collections: /s 0,00 , ns / collections: 19 463 878,17
--------------- END WARMUP ---------------
Objects generated.
Gen 0 ticks: 47584
Gen 0+1 ticks: 472
--------------- BEGIN RUN ---------------
Elapsed: 00:00:00.0206490
TotalCollections [Gen0] - collections: 2,00 ,collections: /s 96,86 , ns / collections: 10 324 530,97
TotalCollections [Gen1] - collections: 1,00 ,collections: /s 48,43 , ns / collections: 20 649 061,95
TotalCollections [Gen2] - collections: 0,00 ,collections: /s 0,00 , ns / collections: 20 649 061,95
--------------- END RUN ---------------
--------------- RESULTS: Tests.GCCollection+Gen1Collection ---------------
Gen 1 collection
--------------- DATA ---------------
TotalCollections [Gen0]: Max: 2,00 collections, Average: 2,00 collections, Min: 2,00 collections, StdDev: 0,00 collections
TotalCollections [Gen0]: Max / s: 96,86 collections, Average / s: 96,86 collections, Min / s: 96,86 collections, StdDev / s: 0,00 collections
TotalCollections [Gen1]: Max: 1,00 collections, Average: 1,00 collections, Min: 1,00 collections, StdDev: 0,00 collections
TotalCollections [Gen1]: Max / s: 48,43 collections, Average / s: 48,43 collections, Min / s: 48,43 collections, StdDev / s: 0,00 collections
TotalCollections [Gen2]: Max: 0,00 collections, Average: 0,00 collections, Min: 0,00 collections, StdDev: 0,00 collections
TotalCollections [Gen2]: Max / s: 0,00 collections, Average / s: 0,00 collections, Min / s: 0,00 collections, StdDev / s: 0,00 collections
--------------- ASSERTIONS ---------------
[PASS] Expected TotalCollections [Gen0] to must be exactly 2,00 collections; actual value was 2,00 collections.
[PASS] Expected TotalCollections [Gen1] to must be exactly 1,00 collections; actual value was 1,00 collections.
[PASS] Expected TotalCollections [Gen2] to must be exactly 0,00 collections; actual value was 0,00 collections.
------------ FINISHED Tests.GCCollection+Gen1Collection ----------
The difference between 47584 ticks for generation 0 and 472 ticks for generation 1 collection is big (more than 100 times), but keep reading because the best is yet to come.
Gen2Collection (objects collected in generation 2 collection)
------------ STARTING Tests.GCCollection+Gen2Collection ----------
Objects generated.
Gen 0 ticks: 46034
Gen 0+1 ticks: 559
Gen 0+1+2 ticks: 1461791
Objects generated.
Gen 0 ticks: 37438
Gen 0+1 ticks: 451
Gen 0+1+2 ticks: 793937
--------------- BEGIN WARMUP ---------------
Elapsed: 00:00:00.3300270
TotalCollections [Gen0] - collections: 3,00 ,collections: /s 9,09 , ns / collections: 110 009 021,88
TotalCollections [Gen1] - collections: 2,00 ,collections: /s 6,06 , ns / collections: 165 013 532,82
TotalCollections [Gen2] - collections: 1,00 ,collections: /s 3,03 , ns / collections: 330 027 065,65
--------------- END WARMUP ---------------
Objects generated.
Gen 0 ticks: 36631
Gen 0+1 ticks: 524
Gen 0+1+2 ticks: 1358065
--------------- BEGIN RUN ---------------
Elapsed: 00:00:00.5528463
TotalCollections [Gen0] - collections: 3,00 ,collections: /s 5,43 , ns / collections: 184 282 119,04
TotalCollections [Gen1] - collections: 2,00 ,collections: /s 3,62 , ns / collections: 276 423 178,56
TotalCollections [Gen2] - collections: 1,00 ,collections: /s 1,81 , ns / collections: 552 846 357,12
--------------- END RUN ---------------
--------------- RESULTS: Tests.GCCollection+Gen2Collection ---------------
Gen 2 collection
--------------- DATA ---------------
TotalCollections [Gen0]: Max: 3,00 collections, Average: 3,00 collections, Min: 3,00 collections, StdDev: 0,00 collections
TotalCollections [Gen0]: Max / s: 5,43 collections, Average / s: 5,43 collections, Min / s: 5,43 collections, StdDev / s: 0,00 collections
TotalCollections [Gen1]: Max: 2,00 collections, Average: 2,00 collections, Min: 2,00 collections, StdDev: 0,00 collections
TotalCollections [Gen1]: Max / s: 3,62 collections, Average / s: 3,62 collections, Min / s: 3,62 collections, StdDev / s: 0,00 collections
TotalCollections [Gen2]: Max: 1,00 collections, Average: 1,00 collections, Min: 1,00 collections, StdDev: 0,00 collections
TotalCollections [Gen2]: Max / s: 1,81 collections, Average / s: 1,81 collections, Min / s: 1,81 collections, StdDev / s: 0,00 collections
--------------- ASSERTIONS ---------------
[PASS] Expected TotalCollections [Gen0] to must be exactly 3,00 collections; actual value was 3,00 collections.
[PASS] Expected TotalCollections [Gen1] to must be exactly 2,00 collections; actual value was 2,00 collections.
[PASS] Expected TotalCollections [Gen2] to must be exactly 1,00 collections; actual value was 1,00 collections.
------------ FINISHED Tests.GCCollection+Gen2Collection ----------
The final results
Gen 0 ticks: 36631
Gen 0+1 ticks: 524
Gen 0+1+2 ticks: 1358065
Yes, the difference between generation 2 and 1 is almost 2600 times!
To be sure below are averages from 5 runs:
Gen 0 ticks: 38364
Gen 0+1 ticks: 424
Gen 0+1+2 ticks: 1403400.6
So generation 1 is surprisingly fast, and generation 2 collection is relatively slow (remember those are ticks! Not milliseconds!). But case closed?
Not exactly.
Take a look at this test:
[PerfBenchmark(Description = "Gen 2 collection with nothing", NumberOfIterations = 1, RunMode = RunMode.Iterations, TestMode = TestMode.Test)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen0, MustBe.ExactlyEqualTo, 3d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen1, MustBe.ExactlyEqualTo, 2d)]
[GcTotalAssertion(GcMetric.TotalCollections, GcGeneration.Gen2, MustBe.ExactlyEqualTo, 1d)]
public void Gen2CollectionWithNothing()
{
_list = null;
var sw = Stopwatch.StartNew();
RunGCAndCheck(0, sw);/* Run collect for gen 0 - collect everything.*/
RunGCAndCheck(1, sw);/* Nothing should be here.*/
RunGCAndCheck(2, sw);/* Nothing should be here.*/
}
It should collect everything in generation 0 collection, the rest should be close to 0, but here are the results:
Gen 0 ticks: 32872
Gen 0+1 ticks: 358
Gen 0+1+2 ticks: 1297617
So yeah. Basically no difference from previous test. So this post should be named “The cost of GC - a failed try”. I don’t know what to make of it. I have some ideas what to change and what to check to be more sure that those numbers are valid.
If anyone has any suggestions I’ve put this code in a repo on github, any pull requests are welcomed.