GC performing full blocking Gen2 collections under SustainedLowLatency despite there is no LowMemory notification from OS
In this post I want to share my observation of a weird behavior in GC.
Background and documented behavior
One can switch GCLatencyMode in order to adjust the GC behavior. According to this doc SustainedLowLatency mode should ensure that full blocking collections are only made under low memory pressure:
(...) The collector tries to perform only generation 0, generation 1, and concurrent generation 2 collections.
Full blocking collections may still occur if the system is under memory pressure
One can subscribe to Full Blocking GC notifications by using Garbage Collection Notifications.
According to CLR via C# book (and you can verify that through debugger like demonstrated in this post) GC subscribes to low memory notifications through usage of CreateMemoryResourceNotification API.
Repro Code
I put together code (by getting and adjusting code sample from mentioned Garbage Collection Notifications msdn doc) that lets you select the GCLatencyMode, runs allocations and display number of performed allocations, number of performed Gen 2 Collections (and how many are blocking) + info about low system memory notification:
namespace GCExperiments
{
using System;
using System.Collections.Generic;
using System.Runtime;
using System.Runtime.InteropServices;
using System.Threading;
public static class Win32Imports
{
public static int LowMemoryResourceNotification = 0;
[DllImport("kernel32.dll", SetLastError = true)]
public static extern IntPtr CreateMemoryResourceNotification(int notificationType);
[DllImport("kernel32.dll", SetLastError = true)]
public static extern bool QueryMemoryResourceNotification(IntPtr hResNotification, out bool isResourceStateMet);
}
public class GCModesTest
{
public static void Main(string[] args)
{
GCModesTest t = new GCModesTest();
t.Run();
}
private List<byte[]> _load = new List<byte[]>();
private IntPtr _hResNotification;
public void Run()
{
Console.WriteLine(
"Press 'I' for test under (I)nteractive GC mode, press 'S' for test under (S)ustainableLowLatency mode and 'L' for test under (L)owLatency mode");
GCLatencyMode requestedMode;
switch (Console.ReadKey(true).Key)
{
case ConsoleKey.I:
requestedMode = GCLatencyMode.Interactive;
break;
case ConsoleKey.S:
requestedMode = GCLatencyMode.SustainedLowLatency;
break;
case ConsoleKey.L:
requestedMode = GCLatencyMode.LowLatency;
break;
default:
Log("Unknown option, exiting");
return;
}
GCSettings.LatencyMode = requestedMode;
Console.WriteLine("Current GC mode: {0}, Is server GC: {1}",
GCSettings.LatencyMode, GCSettings.IsServerGC);
_hResNotification = Win32Imports.CreateMemoryResourceNotification(Win32Imports.LowMemoryResourceNotification);
GC.RegisterForFullGCNotification(1, 1);
ThreadPool.QueueUserWorkItem(o => WaitForFullGCProc());
RunAllocations();
}
private void RunAllocations()
{
try
{
int lastCollCount = 0;
int newCollCount = 0;
int allocations = 0;
while (true)
{
_load.Add(new byte[500]);
allocations++;
newCollCount = GC.CollectionCount(2);
if (newCollCount != lastCollCount)
{
// Show collection count when it increases:
Log("Allocations: {0}. Gen 2 collection count: {1}, from that blocking collections: {2}",
allocations, GC.CollectionCount(2), _gcFullollectionNotificationsCount);
lastCollCount = newCollCount;
}
}
}
catch (OutOfMemoryException)
{
Console.WriteLine("Out of memory.");
}
}
private int _gcFullollectionNotificationsCount = 0;
private void WaitForFullGCProc()
{
// CheckForNotify is set to true and false in Main.
while (true)
{
// Check for a notification of an approaching collection.
GCNotificationStatus s = GC.WaitForFullGCApproach();
if (s == GCNotificationStatus.Succeeded)
{
Log("GC Approach Notification raised.");
}
else if (s == GCNotificationStatus.Canceled)
{
Log("GC Approach Notification cancelled.");
break;
}
else
{
// This can occur if a timeout period
// is specified for WaitForFullGCApproach(Timeout)
// or WaitForFullGCComplete(Timeout)
// and the time out period has elapsed.
Log("GC Approach Notification not applicable.");
break;
}
// Check for a notification of a completed collection.
s = GC.WaitForFullGCComplete();
if (s == GCNotificationStatus.Succeeded)
{
bool isResourceStateMet;
bool succeeded = Win32Imports.QueryMemoryResourceNotification(_hResNotification,
out isResourceStateMet);
if (!succeeded)
{
Log("Call to QueryMemoryResourceNotification failed!");
}
_gcFullollectionNotificationsCount++;
Log(
"GC Completed Notification raised. Count: {0}, Gc gen 2 count: {1}, Is Low memory condition: {2}",
_gcFullollectionNotificationsCount, GC.CollectionCount(2), isResourceStateMet);
}
else if (s == GCNotificationStatus.Canceled)
{
Log("GC Completed Notification not applicable.");
break;
}
else
{
// Could be a time out.
Log("GC Completed Notification not applicable.");
break;
}
}
}
private void Log(string format, params object[] args)
{
Console.WriteLine(format, args);
}
}
}
Observed behavior
When running this code you can see for yourself that under SustainedLowLatency mode the full blocking Gen2 collections are being performed despite the system low memory condition notification is not raised. In fact it runs approximately same number of Gen2 collection and with approximately same frequency as under the Interactive mode, with the difference that all those are blocking under SustainedLowLatency mode. That seems to be contrary to the mentioned documentation.
I have reported this issue to Microsoft and I'll update this post once I have some further info.
Sample outputs
Here goes sample output of provided code for Interactive GC mode:
Press 'I' for test under (I)nteractive GC mode, press 'S' for test under (S)ustainableLowLatency mode and 'L' for test under (L)owLatency mode
Current GC mode: Interactive, Is server GC: False
GC Approach Notification raised.
Allocations: 43050. Gen 2 collection count: 1, from that blocking collections: 0
GC Completed Notification raised. Count: 1, Gc gen 2 count: 1, Is Low memory condition: False
Allocations: 102612. Gen 2 collection count: 2, from that blocking collections: 1
Allocations: 209854. Gen 2 collection count: 3, from that blocking collections: 1
Allocations: 412419. Gen 2 collection count: 4, from that blocking collections: 1
Allocations: 769896. Gen 2 collection count: 5, from that blocking collections: 1
Allocations: 1413345. Gen 2 collection count: 6, from that blocking collections: 1
Allocations: 2640671. Gen 2 collection count: 7, from that blocking collections: 1
Allocations: 4940414. Gen 2 collection count: 8, from that blocking collections: 1
Allocations: 9230099. Gen 2 collection count: 9, from that blocking collections: 1
Allocations: 17166009. Gen 2 collection count: 10, from that blocking collections: 1
Allocations: 23969919. Gen 2 collection count: 11, from that blocking collections: 1
Allocations: 26800670. Gen 2 collection count: 12, from that blocking collections: 1
Allocations: 28591795. Gen 2 collection count: 13, from that blocking collections: 1
And here goes sample output for SustainedLowLatencyMode:
Press 'I' for test under (I)nteractive GC mode, press 'S' for test under (S)ustainableLowLatency mode and 'L' for test under (L)owLatency mode
Current GC mode: SustainedLowLatency, Is server GC: False
GC Approach Notification raised.
Allocations: 43038. Gen 2 collection count: 1, from that blocking collections: 0
GC Completed Notification raised. Count: 1, Gc gen 2 count: 1, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 102584. Gen 2 collection count: 2, from that blocking collections: 1
GC Completed Notification raised. Count: 2, Gc gen 2 count: 2, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 209795. Gen 2 collection count: 3, from that blocking collections: 2
GC Completed Notification raised. Count: 3, Gc gen 2 count: 3, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 424242. Gen 2 collection count: 4, from that blocking collections: 3
GC Completed Notification raised. Count: 4, Gc gen 2 count: 4, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 781680. Gen 2 collection count: 5, from that blocking collections: 4
GC Completed Notification raised. Count: 5, Gc gen 2 count: 5, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 1437019. Gen 2 collection count: 6, from that blocking collections: 5
GC Completed Notification raised. Count: 6, Gc gen 2 count: 6, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 2688148. Gen 2 collection count: 7, from that blocking collections: 6
GC Completed Notification raised. Count: 7, Gc gen 2 count: 7, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 5035521. Gen 2 collection count: 8, from that blocking collections: 7
GC Completed Notification raised. Count: 8, Gc gen 2 count: 8, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 9396673. Gen 2 collection count: 9, from that blocking collections: 8
GC Completed Notification raised. Count: 9, Gc gen 2 count: 9, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 17463633. Gen 2 collection count: 10, from that blocking collections: 9
GC Completed Notification raised. Count: 10, Gc gen 2 count: 10, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 19656130. Gen 2 collection count: 11, from that blocking collections: 10
GC Completed Notification raised. Count: 11, Gc gen 2 count: 11, Is Low memory condition: False
GC Approach Notification raised.
Allocations: 21157575. Gen 2 collection count: 12, from that blocking collections: 11
GC Completed Notification raised. Count: 12, Gc gen 2 count: 12, Is Low memory condition: True
Allocations: 22670954. Gen 2 collection count: 13, from that blocking collections: 12
GC Approach Notification raised.
Allocations: 24241691. Gen 2 collection count: 14, from that blocking collections: 12
GC Completed Notification raised. Count: 13, Gc gen 2 count: 14, Is Low memory condition: True
GC Approach Notification raised.
Allocations: 25856669. Gen 2 collection count: 15, from that blocking collections: 13
As you can see SustainedLowLatency mode is causing approximately same number of collections (despite it's far from low os memory pressure), but all of them are blocking.
Comments
- Anonymous
March 15, 2015
This is bug indeed. But it is not about blocking garbage collections in SustainedLowLatency mode, it is about raising incorrect GC notifications in SustainedLowLatency mode. Basically it notifies you of full GC approaching each time it does any kind (background or full blocking) of GC. To be honest I was extremely concerned when found this blog post. I'm working on low latency GUI application and it is experiencing huge pauses on full blocking GC in Interactive mode. SustainedLowLatency is what I was really counting on. To make things clear I slightly modified your sample above to actually produce some garbage and to avoid out of memory exception. I also made this garbage a bit complicated so compacting phase of GC was supposed to be long and able to cause a pause. I also added code that identifies pauses. My observations are:
- In interactive mode each full blocking GC leads to application virtual memory trimming. So application returns memory back to OS after compacting its heap. At the same time application is experiencing pause.
- In SustainedLowLatency mode no application virtual memory trimming happens most of the time. Nevertheless I'm always notifed of full GC approaching. Also application is not experiencing pauses. Pauses only happens when process virtual memory approaches its limit. This is when full blocking GC happens presumably. With that said I think SustainedLowLatency behaves pretty much as expected. However full GC approaching notification behaves weird in this mode.