PerfView专题 (第七篇)：如何洞察触发 GC 的 C# 代码？

Posted 2022-08-24 dotNET跨平台

一：背景

上一篇我们聊到了如何用 PerfView 洞察 GC 的变化，但总感觉还缺了点什么？对，就是要跟踪到底是什么代码触发了 GC，这对我们分析由于 GC 导致的 CPU 爆高有非常大的参考价值，在以前我都是用 WinDBG 来实现，但这玩意需要做一些侵入性操作，实战起来不是那么丝滑，虽然有可以录制功能的 TTD，所以需寻找完美的解决方案，在此可以借助一下 PerfView 。

二：如何洞察

1. 一个小案例

为了方便讲解，先上一段简单的测试代码，不断的往 List 中塞入数据，可以实现不断的 GC 触发。

namespace ConsoleApp6

    internal class Program
    
        static void Main(string[] args)
        
            Task.Run(Alloc1);

            Console.ReadLine();
        

        static void Alloc1()
        
            List<string> list = new List<string>();

            var rand = new Random();

            for (int i = 0; i < int.MaxValue; i++)
            
                list.Add(string.Join(",", Enumerable.Range(1, 1000)));
                Console.WriteLine(i);
            
        
    

2. WinDbg 拦截

用 windbg 拦截的话非常简单，只需要找到 CoreCLR 中触发 GC 的入口方法，然后下一个断点，再用 k 查看其线程栈即可。

0:012> bp coreclr!WKS::GCHeap::GarbageCollectGeneration
0:012> g
Breakpoint 0 hit
coreclr!WKS::GCHeap::GarbageCollectGeneration:
00007ffa`7823f8cc 48895c2408      mov     qword ptr [rsp+8],rbx ss:00000000`2321f200=00000000006c49f8
0:008> k
 # Child-SP          RetAddr               Call Site
00 00000000`2321f1f8 00007ffa`782f59db     coreclr!WKS::GCHeap::GarbageCollectGeneration [D:\\a\\_work\\1\\s\\src\\coreclr\\gc\\gc.cpp @ 44615] 
01 00000000`2321f200 00007ffa`78337b5d     coreclr!WKS::gc_heap::trigger_gc_for_alloc+0x2b [D:\\a\\_work\\1\\s\\src\\coreclr\\gc\\gc.cpp @ 16846] 
02 00000000`2321f230 00007ffa`782db675     coreclr!WKS::gc_heap::try_allocate_more_space+0x5c4c1 [D:\\a\\_work\\1\\s\\src\\coreclr\\gc\\gc.cpp @ 16977] 
03 00000000`2321f290 00007ffa`78247784     coreclr!WKS::gc_heap::allocate_more_space+0x31 [D:\\a\\_work\\1\\s\\src\\coreclr\\gc\\gc.cpp @ 17447] 
04 (Inline Function) --------`--------     coreclr!WKS::gc_heap::allocate+0x58 [D:\\a\\_work\\1\\s\\src\\coreclr\\gc\\gc.cpp @ 17478] 
05 00000000`2321f2c0 00007ffa`781d9768     coreclr!WKS::GCHeap::Alloc+0x84 [D:\\a\\_work\\1\\s\\src\\coreclr\\gc\\gc.cpp @ 43676] 
06 (Inline Function) --------`--------     coreclr!Alloc+0x125 [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\gchelpers.cpp @ 228] 
07 00000000`2321f2f0 00007ffa`782cc0d9     coreclr!AllocateString+0x19c [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\gchelpers.cpp @ 861] 
08 00000000`2321f390 00007ffa`18782d10     coreclr!FramedAllocateString+0x79 [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\jithelpers.cpp @ 2429] 
09 00000000`2321f4e0 00007ffa`1878687d     System_Private_CoreLib!System.Number.Int32ToDecStr+0xb0
0a 00000000`2321f530 00007ffa`1878668a     System_Private_CoreLib!System.String.JoinCore<int>+0x1bd
0b 00000000`2321f7e0 00007ffa`1877bdcc     System_Private_CoreLib!System.String.Join<int>+0x2a
0c 00000000`2321f820 00007ffa`776d2d0e     ConsoleApp10!ConsoleApp10.Program.Alloc1+0xbc [D:\\net6\\ConsoleApp1\\ConsoleApp10\\Program.cs @ 24] 
0d 00000000`2321f8a0 00007ffa`776d7716     System_Private_CoreLib!System.Threading.Tasks.Task.InnerInvoke+0x1e
0e 00000000`2321f8d0 00007ffa`776bd7f5     System_Private_CoreLib!System.Threading.Tasks.Task.<>c.<.cctor>b__272_0+0x16
0f 00000000`2321f900 00007ffa`776d2a38     System_Private_CoreLib!System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop+0x35
10 00000000`2321f950 00007ffa`776d2943     System_Private_CoreLib!System.Threading.Tasks.Task.ExecuteWithThreadLocal+0x98
11 00000000`2321f9f0 00007ffa`776c6213     System_Private_CoreLib!System.Threading.Tasks.Task.ExecuteEntryUnsafe+0x53
12 00000000`2321fa30 00007ffa`776cdd8a     System_Private_CoreLib!System.Threading.ThreadPoolWorkQueue.Dispatch+0x263
13 00000000`2321fad0 00007ffa`776b278f     System_Private_CoreLib!System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart+0x14a
14 00000000`2321fbe0 00007ffa`7830a853     System_Private_CoreLib!System.Threading.Thread.StartCallback+0x3f
15 00000000`2321fc20 00007ffa`781fd43c     coreclr!CallDescrWorkerInternal+0x83
16 00000000`2321fc60 00007ffa`782ebf93     coreclr!DispatchCallSimple+0x80 [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\callhelpers.cpp @ 220] 
17 00000000`2321fcf0 00007ffa`78258695     coreclr!ThreadNative::KickOffThread_Worker+0x63 [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\comsynchronizable.cpp @ 158] 
18 (Inline Function) --------`--------     coreclr!ManagedThreadBase_DispatchInner+0xd [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\threads.cpp @ 7321] 
19 00000000`2321fd50 00007ffa`7825859a     coreclr!ManagedThreadBase_DispatchMiddle+0x85 [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\threads.cpp @ 7365] 
1a 00000000`2321fe30 00007ffa`782583b9     coreclr!ManagedThreadBase_DispatchOuter+0xae [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\threads.cpp @ 7524] 
1b (Inline Function) --------`--------     coreclr!ManagedThreadBase_FullTransition+0x2d [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\threads.cpp @ 7569] 
1c (Inline Function) --------`--------     coreclr!ManagedThreadBase::KickOff+0x2d [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\threads.cpp @ 7604] 
1d 00000000`2321fed0 00007ffa`e9e47034     coreclr!ThreadNative::KickOffThread+0x79 [D:\\a\\_work\\1\\s\\src\\coreclr\\vm\\comsynchronizable.cpp @ 230] 
1e 00000000`2321ff30 00007ffa`e9f9d0d1     KERNEL32!BaseThreadInitThunk+0x14
1f 00000000`2321ff60 00000000`00000000     ntdll!RtlUserThreadStart+0x21

从输出中可以看到，当前触发的GC的操作是由于 ConsoleApp10!ConsoleApp10.Program.Alloc1+0xbc 方法所致，原因是由于0代阈值用完，但这种调试 CoreCLR 源码的方式终究还是侵入性较大，那有没有自动帮我收集分配 线程调用栈 的工具呢？这就需要借助 PerfView 啦。

3. PerfView 拦截

Windows 系统内置强大的事件跟踪机制（ETW）再次显示出了威力，我们可以用 PerfView 去拦截 GC 的触发事件，并同时记录此时事件触发的调用栈，而且对应用程序的开销非常小。

接下来我们在 Provider Browser 对话框中选择 GCKeyword 选项，

然后再配上一个记录调用栈参数 @StacksEnabled=true, 最后的结果就是：

Microsoft-Windows-DotNETRuntime:GCKeyword:Always:@StacksEnabled=true

配置好之后就可以 Start Collection 了，收集好之后，我们点击面板上的 Events 项，然后输出 GC 关键词，寻找 GC 相关的事件，这里我们看下 GC/Start 事件，如下图所示：

从截图看，非常舒服，清晰的记录着每一个 GC 的详细情况。

HasStack="True" ThreadID="12,912" ProcessorNumber="3" Count="67" Reason="AllocSmall" Depth="0" Type="NonConcurrentGC" ClrInstanceID="8" ClientSequenceNumber="0"

接下来在 Time MSec 列上点击右键选择 Open Any Stacks 打开触发这个 GC 的调用栈代码。

从图中可以非常清晰的看到，Alloc1() 方法触发了 GC 并清晰记录 ETW 事件的全过程，真是太强大，太令人兴奋了。