記一次 .NET 某電子廠OA系統 非託管記憶體洩露分析
一：背景
1.講故事
這周有個朋友找到我，說他的程式出現了記憶體緩慢增長，沒有回頭的趨勢，讓我幫忙看下到底怎麼回事，據朋友說這個問題已經困擾他快一週了，還是沒能找到最終的問題，看樣子這個問題比較刁鑽，不管怎麼說，先祭出 WinDbg。
二：WinDbg 分析
1. 託管還是非託管洩露
一直關注這個系列的朋友都知道，託管和非託管的排查是兩個體系，分析方式完全不一樣，所以要鑑定是哪一塊的記憶體問題，首先要用 !address -summary 觀察程序的 虛擬記憶體 佈局。
0:000> !address -summary
--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free 710 7d93`20465000 ( 125.575 TB) 98.11%
<unknown> 7547 240`9bea8000 ( 2.252 TB) 92.87% 1.76%
Stack 33363 2c`1fae0000 ( 176.495 GB) 7.11% 0.13%
Heap 1179 0`126d3000 ( 294.824 MB) 0.01% 0.00%
Image 2988 0`0c274000 ( 194.453 MB) 0.01% 0.00%
TEB 11121 0`056e2000 ( 86.883 MB) 0.00% 0.00%
Other 11 0`001d9000 ( 1.848 MB) 0.00% 0.00%
PEB 1 0`00001000 ( 4.000 kB) 0.00% 0.00%
--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_MAPPED 7302 200`071b1000 ( 2.000 TB) 82.47% 1.56%
MEM_PRIVATE 45920 6c`cc766000 ( 435.195 GB) 17.52% 0.33%
MEM_IMAGE 2988 0`0c274000 ( 194.453 MB) 0.01% 0.00%
--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE 710 7d93`20465000 ( 125.575 TB) 98.11%
MEM_RESERVE 12136 26c`84ccf000 ( 2.424 TB) 99.94% 1.89%
MEM_COMMIT 44074 0`5aebc000 ( 1.421 GB) 0.06% 0.00%
從卦中看，當前程序的提交記憶體是 MEM_COMMIT= 1.4G， NT堆的記憶體佔用是 Heap=294M，乍一看應該是託管記憶體洩露，接下來用 !eeheap -gc 觀察託管堆。
0:000> !eeheap -gc
Number of GC Heaps: 12
------------------------------
Heap 0 (0000028577D73020)
generation 0 starts at 0x00000285B7000020
generation 1 starts at 0x00000285B6C00020
generation 2 starts at 0x0000028590800020
ephemeral segment allocation context: none
...
------------------------------
GC Allocated Heap Size: Size: 0x9598958 (156862808) bytes.
GC Committed Heap Size: Size: 0xea1c7e0 (245483488) bytes.
從卦中看很奇怪，託管堆也就 GC Committed Heap Size= 245M 的記憶體佔用，說明問題不在託管堆上。
2. 到底是哪裡的洩露
這就是本篇文章的亮點之處，畢竟沒有按照以前的套路出牌，接下來問題在哪裡呢？ 還是得回頭看下 虛擬記憶體佈局，終於你會發現 Stack 處很奇怪，記憶體佔用高達 TotalSize =176G， 記憶體段高達 RgnCount=3.3w，截圖如下：
這兩個蛛絲馬跡已經告訴我們當前開啟了非常多的執行緒，可以用 !address: -f:Stack 觀察執行緒數和執行緒棧資訊。
0:000> !address -f:Stack
BaseAddress EndAddress+1 RegionSize Type State Protect Usage
--------------------------------------------------------------------------------------------------------------------------
c0`80000000 c0`8104b000 0`0104b000 MEM_PRIVATE MEM_RESERVE Stack [~139; 323a8.320a4]
c0`8104b000 c0`8104e000 0`00003000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE | PAGE_GUARD Stack [~139; 323a8.320a4]
c0`8104e000 c0`81050000 0`00002000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Stack [~139; 323a8.320a4]
c0`81050000 c0`8209b000 0`0104b000 MEM_PRIVATE MEM_RESERVE Stack [~140; 323a8.316b8]
c0`8209b000 c0`8209e000 0`00003000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE | PAGE_GUARD Stack [~140; 323a8.316b8]
c0`8209e000 c0`820a0000 0`00002000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Stack [~140; 323a8.316b8]
...
ed`460d0000 ed`4711b000 0`0104b000 MEM_PRIVATE MEM_RESERVE Stack [~11119; 323a8.8b20]
ed`4711b000 ed`4711e000 0`00003000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE | PAGE_GUARD Stack [~11119; 323a8.8b20]
ed`4711e000 ed`47120000 0`00002000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Stack [~11119; 323a8.8b20]
ed`47120000 ed`4816b000 0`0104b000 MEM_PRIVATE MEM_RESERVE Stack [~11120; 323a8.9828]
ed`4816b000 ed`4816e000 0`00003000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE | PAGE_GUARD Stack [~11120; 323a8.9828]
ed`4816e000 ed`48170000 0`00002000 MEM_PRIVATE MEM_COMMIT PAGE_READWRITE Stack [~11120; 323a8.9828]
從卦中看，當前執行緒高達 1.1w 個，有點嚇人，終於算是找到源頭了，
3. 為什麼會有 1w+ 的執行緒
接下來就需要鑑定下這些執行緒是託管執行緒還是非託管執行緒，可以用 !t 觀察。
0:000> !t
ThreadCount: 11104
UnstartedThread: 0
BackgroundThread: 11099
PendingThread: 0
DeadThread: 4
Hosted Runtime: no
Lock
DBG ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
20 1 32588 0000028577D0DB30 202a020 Preemptive 0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA
35 2 3262c 0000028577F3D000 2b220 Preemptive 00000285C0002660:00000285C0004008 0000028577529fc0 -00001 MTA (Finalizer)
36 4 326b4 0000028577F941B0 102b220 Preemptive 0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA (Threadpool Worker)
37 5 31848 000002857811A420 202b220 Preemptive 0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA
...
11116 11100 966c 000002C620A45300 202b220 Preemptive 00000285C86CB910:00000285C86CD868 0000028577529fc0 -00001 MTA
11117 11101 95b4 000002C61B928970 202b220 Preemptive 00000285996DF978:00000285996E18D0 0000028577529fc0 -00001 MTA
11118 11102 9630 000002C61B928FC0 202b220 Preemptive 00000285996E1978:00000285996E38D0 0000028577529fc0 -00001 MTA
11119 11103 8b20 000002C620A465F0 202b220 Preemptive 00000285B46B15C0:00000285B46B3518 0000028577529fc0 -00001 MTA
11120 11104 9828 000002C61E014CB0 202b220 Preemptive 00000285C86CD910:00000285C86CF868 0000028577529fc0 -00001 MTA
從卦中看： DBG 和 ID 的編號相差無幾，說明是大多是託管執行緒，從後面的 MTA 來看，這是一個 new Thread 出來的執行緒，接下來試探看下它有沒有 Name，我們拿 ThreadOBJ=000002C61E014CB0 來看吧。
0:000> dt coreclr!Thread 000002C61E014CB0
...
+0x1c0 m_ExposedObject : 0x00000285`7821d160 OBJECTHANDLE__
...
0:000> !do poi(0x00000285`7821d160)
Name: System.Threading.Thread
MethodTable: 00007ffa63844320
EEClass: 00007ffa6379af48
Tracked Type: false
Size: 72(0x48) bytes
File: D:\root\NewWF\System.Private.CoreLib.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ffa63a0d608 4000b0d 8 ....ExecutionContext 0 instance 00000285c0acf930 _executionContext
00007ffa64cbaa78 4000b0e 10 ...ronizationContext 0 instance 0000000000000000 _synchronizationContext
00007ffa637afd00 4000b0f 18 System.String 0 instance 0000028590888a78 _name
0:000> !DumpObj /d 0000028590888a78
Name: System.String
MethodTable: 00007ffa637afd00
EEClass: 00007ffa6379a6e0
Tracked Type: false
Size: 98(0x62) bytes
File: D:\root\NewWF\System.Private.CoreLib.dll
String: Console logger queue processing thread
經過抽檢，發現執行緒名都是 Console logger queue processing thread，看樣子和紀錄檔有關係，接下來使用 ~*e !clrstack 檢視當前所有執行緒，發現執行緒都卡在 ConsoleLoggerProcessor.TryDequeue 上，截圖如下：
看樣子和微軟的控制檯紀錄檔元件有關係，下一步就要觀察原始碼。
4. 從原始碼中尋找答案
匯出原始碼後，利用 ILSpy 的程式碼回溯功能，發現是 ConsoleLoggerProcessor 類別建構函式 new 出來的執行緒，截圖如下：
結合海量的重複執行緒棧，大概可以猜測到是程式碼將 Singleton 的模式改成了 Transient，導致不斷的 new，不斷的產生新的 Thread 去處理佇列。
接下來我也懶得細究程式碼了，讓朋友重點看一下 Microsoft.Extensions.Logging.Console 元件，朋友也很給力，終於找到了是 AppService 類在不斷的 new 造成的，截圖如下：
三： 總結
這次事故如果朋友有專業的 APM 監控，相信很快就能發現 Thread 爆高的問題，從 dump 中用記憶體來反推執行緒爆高，確實有一點出乎意料。
這個 dump 的教訓是：理解 Singleton 和 Transient 的利弊，儘量遵循官方檔案的寫法吧。