microsoft / perfview

PerfView is a CPU and memory performance-analysis tool
http://channel9.msdn.com/Series/PerfView-Tutorial
MIT License
4.16k stars 708 forks source link

Background GC Collections Missing With ".NET Alloc" Checked #1087

Open luckerby opened 4 years ago

luckerby commented 4 years ago

On a piece of code that generates background GC collections every time it runs (adding 10 mil int values to an ArrayList), I'm seeing different outcomes whether the ".NET Alloc" checkbox in the Advanced Options is set or not.

First, ".NET Alloc" checkbox is NOT set, as follows: image

The corresponding output is below. Note 3 background GCs (2B) happening: image

Next "GC Collect Only" is unchecked and ".NET Alloc" is set. Notice the outcome, and the fact that this time there's no longer any 2B instance: image

The results above are reproducible every time.

Platform specifics:

brianrob commented 4 years ago

@luckerby, this is expected because .NET Alloc is implemented using the profiler API and the implementation specifies COR_PROF_MONITOR_GC. Generally speaking if you want to analyze GC behavior you should not use any of the mechanisms that use the profiler API since this will impact a bunch of runtime behavior. This particular option is good for capturing every allocation, which will still be correct even though the types of GCs that get triggered are different. Does that help?

luckerby commented 4 years ago

I was trying to understand some entries in GCStats that had non-zero "Gen0 Alloc MB" values but 0% "Gen0 Survival Rate%", particularly the objects that would trigger this, given that my code didn't alloc that much in the SOH (not visible unfortunately in the printscreens I pasted). Since the Profiling API requires a full GC in order to do heap traversal, and "count" the space allocated by objects, I didn't find a way to track these objects using a regular memory profiler (eg JetBrains dotMemory, which also uses the Profiling API). Hence the idea of seeing the objects as they are allocated, which as I understand from you, it's not applicable. I did eventually use CLR MD to walk the heap, as no such do-a-full-GC-to-see-the-objects requirement is present there. I did try to find additional info about COR_PROF_MONITOR_GC, but came out empty. Any chance this is documented somewhere publicly ?

brianrob commented 4 years ago

Based on what you are trying to investigate, .NET Alloc should work for you - specifically you should be able to see all allocations. The difference will be how they are collected (you won't see background gen2 GCs when .NET Alloc is enabled). Allocations are likely the right way to attack this problem since you're right that it will be hard to catch the objects before they are collected and by the time the GC occurs they won't be rooted anymore.

There is some information on COR_PROF_MONITOR_GC out there, but it's mixed into the rest of the profiler API documentation. Here's a link to the page that describes what COR_PROF_MONITOR_GC does: https://docs.microsoft.com/en-us/dotnet/framework/unmanaged-api/profiling/cor-prf-monitor-enumeration. Hope that helps.

luckerby commented 4 years ago

Thanks @brianrob. I've been looking at the data so far, and I got this:

  1. From the documentation, we know that COR_PRF_MONITOR_GC disables BGC from occurring
  2. Based on the code, and on a naive mapping between PerfView’s UI tick boxes and the various flags, it appears that “GC Collect” toggles ON COR_PRF_MONITOR_GC
  3. However BGCs are still visible when collecting with “GC Collect” ticked

I'm quite certain that 2. is false, but can't really figure out why. Or, stating in a different way - where can one see that COR_PRF_MONITOR_GC is enabled when ".NET Alloc" is ticked in PerfView's UI ?

brianrob commented 4 years ago

Here's the order of what happens when you check the .NET Alloc checkbox:

  1. When you start collection, the state of the checkbox is saved into the CommandLineArgs object: https://github.com/microsoft/perfview/blob/master/src/PerfView/Dialogs/RunCommandDialog.xaml.cs#L642
  2. Collection is started via ExecuteCommand here: https://github.com/microsoft/perfview/blob/master/src/PerfView/Dialogs/RunCommandDialog.xaml.cs#L812
  3. This results in a call to CommandProcessor.Collect which takes the CommandLineArgs object here: https://github.com/microsoft/perfview/blob/master/src/PerfView/MainWindow.xaml.cs#L1276
  4. Because CommandLineArgs.DotNetAlloc is set to true, the appropriate profilerKeywords are set here: https://github.com/microsoft/perfview/blob/master/src/PerfView/CommandProcessor.cs#L341
  5. This results in the profiler API being configured for all new .NET processes here: https://github.com/microsoft/perfview/blob/master/src/PerfView/CommandProcessor.cs#L356
  6. The profiler API implementation is responsible for hooking the various runtime functions and then emitting ETW events containing the information. Then PerfView can display the data by reading it from the ETL file as opposed to having to have a separate format. As part of collection configuration, PerfView enables the ETW provider that is implemented by the profiler implementation from step 5 here: https://github.com/microsoft/perfview/blob/master/src/PerfView/CommandProcessor.cs#L847
  7. When the profiler implementation is started, the runtime calls CorProfilerTracer::InitializeForAttach which results in a call to EventRegisterETWClrProfiler here: https://github.com/microsoft/perfview/blob/624613f57f9ede8d5d0e2623456cef606a8bb99e/src/EtwClrProfiler/CorProfilerTracer.cpp#L177. This registers ProfilerControlCallback with the OS and says, "Please call this function when you get a request to enable or disable my provider".
  8. Because PerfView already enabled the provider in step 6 ProfilerControlCallback gets called by the OS immediately, which results in a call to DoETWCommand here: https://github.com/microsoft/perfview/blob/624613f57f9ede8d5d0e2623456cef606a8bb99e/src/EtwClrProfiler/CorProfilerTracer.cpp#L100
  9. DoETWCommand figures out that the GCAllocKeyword was specified by PerfView as part of the session configuration, and enables COR_PRF_MONITOR_GC. It then calls m_info->SetEventMask to tell the profiler API here: https://github.com/microsoft/perfview/blob/624613f57f9ede8d5d0e2623456cef606a8bb99e/src/EtwClrProfiler/CorProfilerTracer.cpp#L320

It's a pretty verbose handshake, but that's how it works. For number 2, I think you're talking about GC Collect Only. That won't enable any of this - it just enables a handful of GC ETW events that are built into the runtime. There is no profiler API involved which is why you still see BGCs.