一:背景
上一篇我们聊到了如何用 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::GarbageCollectGeneration0:012> gBreakpoint 0 hitcoreclr!WKS::GCHeap::GarbageCollectGeneration:00007ffa`7823f8cc 48895c2408 mov qword ptr [rsp+8],rbx ss:00000000`2321f200=00000000006c49f80:008> k # Child-SP RetAddr Call Site00 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+0xb00a 00000000`2321f530 00007ffa`1878668a System_Private_CoreLib!System.String.JoinCore<int>+0x1bd0b 00000000`2321f7e0 00007ffa`1877bdcc System_Private_CoreLib!System.String.Join<int>+0x2a0c 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+0x1e0e 00000000`2321f8d0 00007ffa`776bd7f5 System_Private_CoreLib!System.Threading.Tasks.Task.<>c.<.cctor>b__272_0+0x160f 00000000`2321f900 00007ffa`776d2a38 System_Private_CoreLib!System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop+0x3510 00000000`2321f950 00007ffa`776d2943 System_Private_CoreLib!System.Threading.Tasks.Task.ExecuteWithThreadLocal+0x9811 00000000`2321f9f0 00007ffa`776c6213 System_Private_CoreLib!System.Threading.Tasks.Task.ExecuteEntryUnsafe+0x5312 00000000`2321fa30 00007ffa`776cdd8a System_Private_CoreLib!System.Threading.ThreadPoolWorkQueue.Dispatch+0x26313 00000000`2321fad0 00007ffa`776b278f System_Private_CoreLib!System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart+0x14a14 00000000`2321fbe0 00007ffa`7830a853 System_Private_CoreLib!System.Threading.Thread.StartCallback+0x3f15 00000000`2321fc20 00007ffa`781fd43c coreclr!CallDescrWorkerInternal+0x8316 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+0x141f 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 事件的全过程,真是太强大,太令人兴奋了。