Why does the GC not suspend a thread doing ETW rundown?

[cosminvlad]

Description

In a pretty large .net core 3.1 app deployed in Azure, we see large GC pauses (up to 10 seconds). Upon investigation, we have determined that the time is spent by GC in the suspend stage and the only thread that runs is one that does an ETW rundown (Azure automatically takes profiler traces from time to time). Because the app is pretty large, the rundown process takes up 10s to enumerate ~200k methods (large app, uses many libraries).

We want to understand what is so special about this thread / process that GC just waits for it and why it can't suspend it in the middle of a rundown.

Configuration

• Which version of .NET is the code running on?
  .net core 3.1.6
• What OS version, and what distro if applicable?
  Windows Server 2016
• What is the architecture (x64, x86, ARM, ARM64)?
  x64

Data

GC takes >10s

Events like these both before and after the GC starts

Events DCStartVerbose and ILToNativeMapDCStart go on for 10s. Only after they stop do we find SuspendEEStop

Stack trace of thread doing rundown

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

[mjsabby]

Relevant: dotnet/coreclr#8357 and #13571

[mangod9]

Hey @cosminvlad, Thanks for reporting the issue. How often do these long GC pauses occur for your application? The issue @mjsabby refers to looks to have fixed a part of this, but moving to tracking area-path. @noahfalk, please let us know if this needs further investigation from VM/GC perspective.

[tommcdon]

@sywhang @josalem

[noahfalk]

Thanks for report @cosminvlad!

I'm not sure the issue @mjsabby referenced is likely to be the culprit here. Following the code that Vance changed back upwards in the call graph shows he was addressing a hang that occurred during the GC (after the suspend is complete) but the symptom here is that suspend itself is slow. PerfView can collect more detailed information that would probably identify the culprit using a thread time trace, for example:

PerfView.exe /nogui /accepteula /StopOnGCSuspendOverMSec:500 /Process:MyProcess /DelayAfterTriggerSec:0 /CollectMultiple:3 /KernelEvents=ThreadTime+Memory+VirtualAlloc /ClrEvents:GC+Stack /BufferSize:3000 /CircularMB:3000 collect

There is more info about diagnosing long suspensions in @Maoni0's blog if you are interested: https://devblogs.microsoft.com/dotnet/work-flow-of-diagnosing-memory-performance-issues-part-2/

Getting the thread time trace would be ideal if possible to narrow in on exactly what causes the issue. Without the trace we could still do some code research and perhaps we'd find something apparent in how the code utilizes that CodeHeapIterator lock.

[vas6ili]

I'm part of the same team as @cosminvlad, he's on PTO this week and couldn't follow up on this, but I can give a bit more context.

These profiler traces were taken for an Azure App Service. The app also is integrated with Application Insights which has a "profiler trace sample" feature that gets triggered automatically based on conditions like slower response time. We've noticed large suspend pause times in these profiler traces.

How often do these long GC pauses occur for your application?

We had a bug in this app, a background job would run periodically and allocate more than necessary, thus triggering GC more often (up to 10x). More frequent GC increased the likelihood of it occuring while a profiler trace running, started automatically by Application Insights. We have since fixed our high GC count problem and disabled the "automatic profiler" feature. Still, one couldn't hope to eliminate GC completely so there's always a small chance of this issue happening if the profiler is back on.

Getting the thread time trace would be ideal if possible to narrow in on exactly what causes the issue.

Thanks for the info, I'll try to reproduce it locally and run PerfView with the arguments above