1sec Long Pause (stop-the-world) on Gen1 GC

[dickens-code]

Description

Recently my team has been working on lowering down memory allocation to minimize GC pressure.
While we used different technique to reuse/recycle object, or use ArrayPool.Shared to rent/return memory, we found that there are periodic long pauses (~1s, stop-the-world) of Gen0/Gen1 GC few times per hour.
We used PerfView command to spot it out:

PerfView -NoGui -AcceptEULA -NoNGenRundown -BufferSizeMB:2048 -CircularMB:2048 -Zip:false -Merge:true -ClrEvents:GC+Stack -StopOnGCOverMSec:300 -KernelEvents:Memory,VirtualAlloc,Default -OnlyProviders:ClrPrivate:1:5,Clr:0x40000001:5 -NoRundown
-DelayAfterTriggerSec:0 -CollectMultiple:1 -DataFile:XXX-2307051821-48272-gcsg -FocusProcess:48272 -Process:48272 collect

GC Stats showing 1s Gen1 GC pause

[pic1]

The Gen0 Frag% is obvious very high (98.98%) ...
If I looked into CPU Stack with filter applied for GC period, looks like most CPU time is used for doing compact?

When looking into the CPU Stack of profile, we discovered that these few calls during GC causes most part of delay:

1. coreclr!SyncBlockCache::InsertCleanupSyncBlock
2. coreclr!SVR::GCHeap::IsPromoted
3. ntoskrnl!MiRemoveLowestPriorityStandbyPage

[pic2]

When firing up Goto Source these lines are most time consuming ...
InsertCleanupSyncBlock

[pic3]

IsPromoted

[pic4]

Would you mind telling us that what would be the root cause of it, and anything we can do to prevent such long app pause (1N Gen1 non-concurrent GC)? Or how to solve fragmentation problem if that is the root cause?

Thanks a lot~
dickens

Configuration

• .NET 7
• App running in GC Server mode, with GC affinity set to 0:0-62
• Windows Server 2012 x64, 128 cores, 2 NUMA nodes
• Cloud server on AWS

Tagging subscribers to this area: @dotnet/gc
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

Recently my team has been working on lowering down memory allocation to minimize GC pressure.
While we used different technique to reuse/recycle object, or use ArrayPool.Shared to rent/return memory, we found that there long periodic long pauses (~1s) of Gen0/Gen1 GC few times per hour.
We used PerfView command to spot it out:

PerfView -NoGui -AcceptEULA -NoNGenRundown -BufferSizeMB:2048 -CircularMB:2048 -Zip:false -Merge:true -ClrEvents:GC+Stack -StopOnGCOverMSec:300 -KernelEvents:Memory,VirtualAlloc,Default -OnlyProviders:ClrPrivate:1:5,Clr:0x40000001:5 -NoRundown
-DelayAfterTriggerSec:0 -CollectMultiple:1 -DataFile:XXX-2307051821-48272-gcsg -FocusProcess:48272 -Process:48272 collect

GC Stats showing 1s Gen1 GC pause

[pic1]

When looking into the CPU Stack of profile, we discovered that these few calls during GC causes most part of delay:

1. coreclr!SyncBlockCache::InsertCleanupSyncBlock
2. coreclr!SVR::GCHeap::IsPromoted
3. ntoskrnl!MiRemoveLowestPriorityStandbyPage
   
   [pic2]

When Goto Source these lines are most time consuming ...
InsertCleanupSyncBlock

[pic3]

IsPromoted

[pic4]

Configuration

.NET core 7
Windows Server 2012 x64

Author:	dickens-code
Assignees:	-
Labels:	tenet-performance, area-GC-coreclr, untriaged
Milestone:	-

[mangod9]

Hello @dickens-code , would it possible to securely share the traces you have collected? Also are you observing that this has regressed in .NET 7?

[dickens-code]

yes, it is happening to net7, however I can't share the profile (etl file) to you due to security reason. Anything I should check?

[mangod9]

would it be possible to collect some GCCollectOnly traces? That shouldnt have much PII or other info.

[cshung]

@mangod9, I am working with @dickens-code offline to diagnose the issue. We will report findings here whenever we make progress.

[dickens-code]

thanks both @mangod9 and @cshung ~