PerfView專題 (第十篇)：洞察 C# 終結隊列引發的記憶體泄漏
一：背景
C# 程式記憶體泄漏的誘發因素有很多，但從頂層原理上來說，就是該銷毀的 用戶根 對象沒有被銷毀，從而導致記憶體中意料之外的對象無限堆積，導致記憶體暴漲，最終崩潰，這其中的一個用戶根就是 終結器隊列，這一篇我們就來看下如何讓 PerfView 配合 WinDbg 雙劍合璧。
二：如何洞察
1. 終結器記憶體泄漏
為了模擬 終結器記憶體泄漏，我們故意在 析構函數 中執行複雜的邏輯，讓析構過程足夠的慢,這樣可以實現 分配速度 遠大於 銷毀速度 ，達到消費能力不足引發的記憶體暴漲， 參考如下程式碼：
internal class Program
{
static void Main(string[] args)
{
Task.Run(Add);
Console.ReadLine();
}
static void Add()
{
for (int i = 0; i < 1000000; i++)
{
var person = new Person() { Name = $"jack{i}", Age = i };
}
}
}
public class Person
{
public string Name { get; set; }
public int Age { get; set; }
~Person()
{
Thread.Sleep(new Random().Next(0,3000));
Console.WriteLine($"name={Name} 已析構了哦 ...");
}
}
當分配操作結束後，用 WinDbg 附加到進程中，使用 !fq 查看記憶體情況,輸出如下：
0:015> !fq
SyncBlocks to be cleaned up: 0
Free-Threaded Interfaces to be released: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
generation 0 has 28423 finalizable objects (000000001BF5B108->000000001BF92940)
generation 1 has 4 finalizable objects (000000001BF5B0E8->000000001BF5B108)
generation 2 has 21 finalizable objects (000000001BF5B040->000000001BF5B0E8)
Ready for finalization 971560 objects (000000001BF92940->000000001C6FC280)
Statistics for all finalizable objects (including all objects ready for finalization):
MT Count TotalSize Class Name
00007ffdbaa2f410 4 96 System.WeakReference
00007ffdbaa4f368 2 112 System.Threading.ThreadPoolWorkQueueThreadLocals
00007ffdbaa4c640 1 168 System.Diagnostics.Tracing.FrameworkEventSource
00007ffdbaa417b8 1 168 System.Diagnostics.Tracing.NativeRuntimeEventSource
00007ffdbaa4a158 1 176 System.Threading.Tasks.TplEventSource
00007ffdbaa05650 3 216 System.Threading.Thread
00007ffdbaa240a8 1 320 System.Diagnostics.Tracing.RuntimeEventSource
00007ffdbaa24ac8 8 896 System.Diagnostics.Tracing.EventSource+OverideEventProvider
00007ffdbaa4fb58 999987 31999584 ConsoleApp2.Person
Total 1000008 objects
從上面的 Ready for finalization 971560 objects 中可以看到，當前有 9.7w 的對象正在排隊等待 Finalizer 執行緒執行，既然它可以執行，為什麼執行這麼慢呢？ 這時候就需要調查下 Finalizer Thread 此時正在幹嘛。
0:001> !t
ThreadCount: 7
UnstartedThread: 0
BackgroundThread: 6
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 4f98 000000000058C270 2a020 Preemptive 0000000000000000:0000000000000000 00000000005814e0 1 MTA
5 2 3f4c 000000001AA94090 202b220 Preemptive 00000000088A9D60:00000000088A9FD0 00000000005814e0 0 MTA (Finalizer)
7 3 24b8 000000001AA986D0 102a220 Preemptive 0000000000000000:0000000000000000 00000000005814e0 0 MTA (Threadpool Worker)
11 4 5520 000000000056F580 1029220 Preemptive 00000000088A5100:00000000088A5FD0 00000000005814e0 0 MTA (Threadpool Worker)
12 5 1004 000000001AB26160 1029220 Preemptive 0000000000000000:0000000000000000 00000000005814e0 0 MTA (Threadpool Worker)
13 6 58a8 000000001B6D35D0 21220 Preemptive 0000000000000000:0000000000000000 00000000005814e0 0 Ukn
14 7 5b8 000000001B650820 1029220 Preemptive 0000000000000000:0000000000000000 00000000005814e0 0 MTA (Threadpool Worker)
0:001> ~~[3f4c]s
ntdll!NtDelayExecution+0x14:
00007ffe`8908c634 c3 ret
0:005> !clrstack
OS Thread Id: 0x3f4c (5)
Child SP IP Call Site
000000001ACEF868 00007ffe8908c634 [HelperMethodFrame: 000000001acef868] System.Threading.Thread.SleepInternal(Int32)
000000001ACEF960 00007ffe19f0c46b System.Threading.Thread.Sleep(Int32) [/_/src/System.Private.CoreLib/src/System/Threading/Thread.CoreCLR.cs @ 259]
000000001ACEF990 00007ffdba986e15 ConsoleApp2.Person.Finalize() [D:\net6\ConsoleApp1\ConsoleApp2\Program.cs @ 31]
000000001ACEFCE0 00007ffe1a4a6c06 [DebuggerU2MCatchHandlerFrame: 000000001acefce0]
從輸出中可以看到，終結器執行緒正在 Sleep() 函數，如果你有源碼的話，可以看下 ConsoleApp2.Person.Finalize() 中的具體業務邏輯，如果沒有源碼的話，可以使用 !U 00007ffdba986e15 反彙編下方法源碼。
0:005> !U 00007ffdba986e15
Normal JIT generated code
ConsoleApp2.Person.Finalize()
ilAddr is 00000000023920E0 pImport is 0000000002FFF460
Begin 00007FFDBA986DA0, size e9
D:\net6\ConsoleApp1\ConsoleApp2\Program.cs @ 31:
00007ffd`ba986dd4 48b998b4a6bafd7f0000 mov rcx,7FFDBAA6B498h (MT: System.Random)
00007ffd`ba986dde e85d0ab25f call coreclr!JIT_TrialAllocSFastMP_InlineGetThread (00007ffe`1a4a7840)
00007ffd`ba986de3 488945f8 mov qword ptr [rbp-8],rax
00007ffd`ba986de7 488b4df8 mov rcx,qword ptr [rbp-8]
00007ffd`ba986deb e848fdffff call 00007ffd`ba986b38 (System.Random..ctor(), mdToken: 00000000060015AB)
00007ffd`ba986df0 488b4df8 mov rcx,qword ptr [rbp-8]
00007ffd`ba986df4 33d2 xor edx,edx
00007ffd`ba986df6 41b8b80b0000 mov r8d,0BB8h
00007ffd`ba986dfc 488b45f8 mov rax,qword ptr [rbp-8]
00007ffd`ba986e00 488b00 mov rax,qword ptr [rax]
00007ffd`ba986e03 488b4040 mov rax,qword ptr [rax+40h]
00007ffd`ba986e07 ff5030 call qword ptr [rax+30h]
00007ffd`ba986e0a 8945f4 mov dword ptr [rbp-0Ch],eax
00007ffd`ba986e0d 8b4df4 mov ecx,dword ptr [rbp-0Ch]
00007ffd`ba986e10 e833e7feff call 00007ffd`ba975548 (System.Threading.Thread.Sleep(Int32), mdToken: 0000000006001CD5)
>>> 00007ffd`ba986e15 90 nop
D:\net6\ConsoleApp1\ConsoleApp2\Program.cs @ 32:
00007ffd`ba986e16 488b0c25f0305d12 mov rcx,qword ptr [125D30F0h] ("name=")
00007ffd`ba986e1e 48894de8 mov qword ptr [rbp-18h],rcx
00007ffd`ba986e22 488b4d10 mov rcx,qword ptr [rbp+10h]
00007ffd`ba986e26 e89dcfffff call 00007ffd`ba983dc8 (ConsoleApp2.Person.get_Name(), mdToken: 0000000006000004)
00007ffd`ba986e2b 488945e0 mov qword ptr [rbp-20h],rax
00007ffd`ba986e2f 4c8b0425f8305d12 mov r8,qword ptr [125D30F8h] ("")
00007ffd`ba986e37 488b4de8 mov rcx,qword ptr [rbp-18h]
00007ffd`ba986e3b 488b55e0 mov rdx,qword ptr [rbp-20h]
00007ffd`ba986e3f e864d7feff call 00007ffd`ba9745a8 (System.String.Concat(System.String, System.String, System.String), mdToken: 0000000006000705)
00007ffd`ba986e44 488945d8 mov qword ptr [rbp-28h],rax
00007ffd`ba986e48 488b4dd8 mov rcx,qword ptr [rbp-28h]
00007ffd`ba986e4c e8cf99ffff call 00007ffd`ba980820 (System.Console.WriteLine(System.String), mdToken: 0000000006000081)
00007ffd`ba986e51 90 nop
00007ffd`ba986e52 90 nop
00007ffd`ba986e53 eb00 jmp 00007ffd`ba986e55
00007ffd`ba986e55 488bcc mov rcx,rsp
00007ffd`ba986e58 e808000000 call 00007ffd`ba986e65 (ConsoleApp2.Person.Finalize(), mdToken: 0000000006000008)
00007ffd`ba986e5d 90 nop
D:\net6\ConsoleApp1\ConsoleApp2\Program.cs @ 33:
00007ffd`ba986e5e 90 nop
00007ffd`ba986e5f 488d6500 lea rsp,[rbp]
00007ffd`ba986e63 5d pop rbp
00007ffd`ba986e64 c3 ret
最終我們找到了問題原因，在真實項目中肯定不會這麼簡單的，往往會執行一個複雜的邏輯，接下來我們就有一個好奇點了，那個 複雜的邏輯 會大概執行多久呢？
因為 dump 只是一個靜態快照，所以從 dump 中尋找的路子就封死了，那有沒有方案呢？ 肯定有啦，讓 PerfView 大威天龍。
2. Finalize() 到底有多慢
在 CoreCLR 中有一些監控 Finalizer Thread 執行緒的 ETW 事件，具體是：
1）FinalizersStart 事件
2）FinalizerObject 事件
3）FinalizersStop 事件
當一個對象準備析構時，會觸發 FinalizerObject ETW事件，所以觀察對象之間的析構間隔，大概就能看出大致的 耗費時間。
知道原理之後，接下來打開 PerfView，使用默認設置，啟用 Collect -> Collect 收集，然後把應用程式跑起來，運行一段時間後，點擊 Stop Collection ，在生成的 zip 面板中點擊 Event ，搜索 Finalize 關鍵詞，截圖如下：
從圖中可以看到，TypeName 列都是 Person 對象，而且從 Time MSec 時間戳上可以觀察到 Person 和 Person 之間相隔 s 級以上，起碼說明析構函數 執行真的很慢。
