一:背景 1. 講故事 前些天有位朋友找到我,說他生產上的程式有記憶體暴漲情況,讓我幫忙看下怎麼回事,最簡單粗暴的方法就是讓朋友在記憶體暴漲的時候抓一個dump下來,看一看大概就知道咋回事了。 二:Windbg 分析 1. 到底是誰吃了記憶體 這個問題說的再多也不為過,一定要看清楚這個程式是如何個性化發展 ...
一:背景
1. 講故事
前些天有位朋友找到我,說他生產上的程式有記憶體暴漲情況,讓我幫忙看下怎麼回事,最簡單粗暴的方法就是讓朋友在記憶體暴漲的時候抓一個dump下來,看一看大概就知道咋回事了。
二:Windbg 分析
1. 到底是誰吃了記憶體
這個問題說的再多也不為過,一定要看清楚這個程式是如何個性化發展的,可以使用 !address -summary
命令。
0:000> !address -summary
--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free 255 7dfb`064e1000 ( 125.981 TB) 98.42%
<unknown> 529 204`d53ac000 ( 2.019 TB) 99.97% 1.58%
Heap 889 0`170f0000 ( 368.938 MB) 0.02% 0.00%
Image 1214 0`07a9a000 ( 122.602 MB) 0.01% 0.00%
Stack 192 0`05980000 ( 89.500 MB) 0.00% 0.00%
Other 10 0`001d8000 ( 1.844 MB) 0.00% 0.00%
TEB 64 0`00080000 ( 512.000 kB) 0.00% 0.00%
PEB 1 0`00001000 ( 4.000 kB) 0.00% 0.00%
--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE 255 7dfb`064e1000 ( 125.981 TB) 98.42%
MEM_RESERVE 709 204`43eab000 ( 2.017 TB) 99.86% 1.58%
MEM_COMMIT 2190 0`b5c64000 ( 2.840 GB) 0.14% 0.00%
從卦象看進程記憶體也才 2.84G
,嚴格來說也不算多,可能朋友抓的有點心急,從上面的 unknown
指標看大概率是托管堆的暴漲,繼續使用 !eeheap -gc
觀察下托管堆。
0:000> !eeheap -gc
========================================
Number of GC Heaps: 4
----------------------------------------
Heap 0 (000001d0adf50a20)
generation 0 starts at 1d0b3fad350
generation 1 starts at 1d0b3f9be88
generation 2 starts at 1d0ae5d1000
ephemeral segment allocation context: none
Small object heap
segment begin allocated committed allocated size committed size
01d0ae5d0000 01d0ae5d1000 01d0b4046258 01d0b48ac000 0x5a75258 (94851672) 0x62dc000 (103661568)
Large object heap starts at 1d4ae5d1000
segment begin allocated committed allocated size committed size
01d4ae5d0000 01d4ae5d1000 01d4b6d0c4e8 01d4b6d2d000 0x873b4e8 (141800680) 0x875d000 (141938688)
Pinned object heap starts at 1d4ee5d1000
segment begin allocated committed allocated size committed size
01d4ee5d0000 01d4ee5d1000 01d4ee5e4f08 01d4ee5f2000 0x13f08 (81672) 0x22000 (139264)
------------------------------
...
Heap 3 (000001d0ae4fd000)
generation 0 starts at 1d3b26929e0
generation 1 starts at 1d3b2687ad8
generation 2 starts at 1d3ae5d1000
ephemeral segment allocation context: none
Small object heap
segment begin allocated committed allocated size committed size
01d3ae5d0000 01d3ae5d1000 01d4179a5980 01d418021000 0x693d4980 (1765624192) 0x69a51000 (1772425216)
Large object heap starts at 1d4de5d1000
segment begin allocated committed allocated size committed size
01d4de5d0000 01d4de5d1000 01d4df8836d8 01d4df884000 0x12b26d8 (19605208) 0x12b4000 (19611648)
Pinned object heap starts at 1d51e5d1000
segment begin allocated committed allocated size committed size
01d51e5d0000 01d51e5d1000 01d51e5dd7e0 01d51e5e2000 0xc7e0 (51168) 0x12000 (73728)
------------------------------
GC Allocated Heap Size: Size: 0x8a6b9060 (2322305120) bytes.
GC Committed Heap Size: Size: 0x8c6b1000 (2355826688) bytes.
從GC堆看果然是托管層的問題,繼續使用 !dumpheap -stat
觀察下托管堆的現狀,看看哪一位是罪魁禍首。
0:000> !dumpheap -stat
Statistics:
MT Count TotalSize Class Name
...
7fff32e81db8 43 68,801,032 SmartMeter.Mem.TerminalInfo[]
7fff329f7470 200,000 110,400,000 SmartMeter.Model.MeterInfo_Model
7fff3227d708 2,285,392 116,193,998 System.String
01d0ae46b350 543 1,857,281,320 Free
Total 3,947,969 objects, 2,314,533,332 bytes
Fragmented blocks larger than 0.5 MB:
Address Size Followed By
01d0ae935870 723,384 01d0ae9e6228 System.SByte[]
01d1b41d3cd0 23,081,616 01d1b57d6f60 System.Byte[]
01d3b274eb40 1,696,943,656 01d4179a3968 System.Byte[]
這卦不看不知道,一看嚇一跳,這2.3G
的記憶體,居然被一個 1.69G
的Free給侵吞了,不信的話可以用 !do
驗證下。
0:000> !do 01d3b274eb40
Free Object
Size: 1696943656(0x65254e28) bytes
2. 為什麼會有這麼大的Free
這是一個值得思考的問題,也決定著我們下一步分析的方向,接下來就是看下這個 free 的落腳點以及周圍對象的分佈情況,可以使用 !gcwhere
觀察。
0:000> !gcwhere 01d3b274eb40
Address Heap Segment Generation Allocated Committed Reserved
01d3b274eb40 3 01d3ae5d0000 0 1d3ae5d1000-1d4179a5980 1d3ae5d0000-1d418021000 1d418021000-1d4ae5d0000
0:000> !dumpheap -segment 1d3ae5d0000
...
01d3b274e948 7fff32468658 96
01d3b274e9a8 7fff3227d708 28
01d3b274e9c8 7fff3227d708 28
01d3b274e9e8 7fff32d0c8d8 80
01d3b274ea38 7fff3227d708 96
01d3b274ea98 7fff32d0aa38 40
01d3b274eac0 01d0ae46b350 128 Free
01d3b274eb40 01d0ae46b350 1,696,943,656 Free
01d4179a3968 7fff323e1638 8,216
從卦象看挺遺憾的,如果 Free 落在segment的最後一個位置,那麼 segment 就會 uncommitted 進而記憶體就下去了,可偏偏最後一個位置是 8216byte 的對象占據著,阻止了記憶體的回收,有經驗的朋友可能知道,這個對象非富即貴,大概率是被 pinned 了,可以用 !gcroot
觀察下。
0:000> !gcroot 01d4179a3968
HandleTable:
000001d0ae3927f8 (async pinned handle)
-> 01d3b26706f0 System.Threading.OverlappedData
-> 01d4179a3968 System.Byte[]
Found 1 unique roots.
0:000> !dumpobj /d 1d4179a3968
Name: System.Byte[]
MethodTable: 00007fff323e1638
EEClass: 00007fff323e15b8
Tracked Type: false
Size: 8216(0x2018) bytes
Array: Rank 1, Number of elements 8192, Type Byte (Print Array)
Content: ............L.o.g.\.2.0.2.3.0...
Fields:
None
從上面的 async pinned handle
來看是一個文件監控的回調函數,到這裡就可以從表象解釋:是這個 8216 的對象導致的記憶體無法回收。
3. 真的要 8216 來擔責嗎
如果你真的要讓 8216 來擔責,那真的只看到了表象,記憶體的突然暴漲回不去只是恰好遇到了 8216 的阻止,但它不是本質原因,真正要考慮的是為什麼GC回收後會產生這麼大一個單獨 Free,其實隱喻了當前程式出現過短時的 大對象分配
,對,就是這個詞。
接下來的問題是如何找到這個 大對象分配
呢? 最好的方法就是用 perfview
的 .NET SampAlloc 去洞察,如果非要用 WinDbg 的話那就只能看看 Free 生前是什麼,或許能尋找到答案,可以藉助 .writemem
命令觀察。
0:000> !do 01d3b274eb40
Free Object
Size: 1696943656(0x65254e28) bytes
0:000> .writemem D:\testdump\1.txt 01d3b274eb40 L?0x65254e28
Writing 65254e28 bytes................
從卦中數據看有大量的計費信息,看樣子又是從資料庫中短時的撈取了大批量數據在托管堆上折騰導致的,知道了本質原因,解決辦法就比較簡單了,通常有兩種做法。
-
修改 GC 模式,改成 Workstation。
-
大批量數據 改成 小步快跑
三:總結
這起記憶體暴漲事故,表象上是 8216 的阻擋導致了記憶體無法被uncommitted所致,本質上還是歸於托管堆的 記憶體黑洞
現象。