PerfView專題 (第七篇)：如何洞察觸發 GC 的 C# 程式碼？

2022 年 8 月 21 日
筆記
perfview

一：背景

上一篇我們聊到了如何用 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 事件的全過程，真是太強大，太令人興奮了。

Tags: perfview