記一次 .NET 某電力系統 記憶體暴漲分析

一線碼農發表於2023-09-18

一:背景

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所致,本質上還是歸於託管堆的 記憶體黑洞 現象。

相關文章