記一次 .NET 某外貿ERP 記憶體暴漲分析

2023-04-23 12:00:37

一:背景

1. 講故事

上週有位朋友找到我,說他的 API 被多次呼叫後出現了記憶體暴漲,讓我幫忙看下是怎麼回事?看樣子是有些擔心,但也不是特別擔心,那既然找到我,就給他分析一下吧。

二:WinDbg 分析

1. 到底是哪裡的洩露

這也是我一直在訓練營灌輸的理念,一定要知道是哪一邊的暴漲,否則很可能就南轅北轍了,使用 !address -summary!eeheap -gc 即可。


0:000> !address -summary

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                                    315     7df9`dbf15000 ( 125.976 TB)           98.42%
<unknown>                              1056      206`130ec000 (   2.024 TB)  99.99%    1.58%
Image                                  1262        0`091ee000 ( 145.930 MB)   0.01%    0.00%
Heap                                    258        0`04c19000 (  76.098 MB)   0.00%    0.00%
Stack                                   114        0`02fc0000 (  47.750 MB)   0.00%    0.00%
Other                                     9        0`001db000 (   1.855 MB)   0.00%    0.00%
TEB                                      38        0`0004c000 ( 304.000 kB)   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                              260      200`01dbf000 (   2.000 TB)  98.82%    1.56%
MEM_PRIVATE                            1216        6`1912e000 (  24.392 GB)   1.18%    0.02%
MEM_IMAGE                              1262        0`091ee000 ( 145.930 MB)   0.01%    0.00%

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                315     7df9`dbf15000 ( 125.976 TB)           98.42%
MEM_RESERVE                             492      205`3abc6000 (   2.020 TB)  99.82%    1.58%
MEM_COMMIT                             2246        0`e9515000 (   3.646 GB)   0.18%    0.00%
....

0:000> !eeheap -gc
Number of GC Heaps: 8
------------------------------
....
------------------------------
GC Allocated Heap Size:    Size: 0x74d77d98 (1960279448) bytes.
GC Committed Heap Size:    Size: 0xcb7c6000 (3413925888) bytes.

從卦中看,當前提交記憶體是 3.64G ,託管堆的提交記憶體是 3.41G,很明顯這是一個 託管記憶體 暴漲,到這裡就比較好解決了。

不知道可有朋友注意到了 GC Allocated Heap SizeGC Committed Heap Size 相差甚大,高達 1.5G 之多,上次看到這個情況還是 某電廠 的一個 dump,當時還問了下 Maoni ,說是設計如此,既然說到了設計如此,我還看了下 .NET 版本是 .NET5,所以冷不丁的看下來這個程式的.NET版本,輸出如下:


0:000> !eeversion
5.0.621.22011 free
5,0,621,22011 @Commit: 478b2f8c0e480665f6c52c95cd57830784dc9560
Server mode with 8 gc heaps
SOS Version: 6.0.5.7301 retail build

我去 .NET5 再現,其實到這裡可以這麼說, 至少我覺得 .NET5 在這一塊還可以再優化優化。

2. 為什麼會相距過大

電廠 的那個dump中,後來通過非託管分析,發現有大量的統計資訊,後來確認是網站上有一段時間的高頻匯入匯出檔案造成的暴漲,這句話的意思就是程式曾經出現過短暫的 快進快出,這就意味著有大量短暫的臨時物件產生, CLR 為了高效處理,在短暫物件釋放後,並沒有將記憶體歸還給 作業系統, 而是自己私吞,目的是防未來可能的爆炸性的記憶體分配,所以你會看到 分配區域提交區域 過大的底層邏輯了。

原理大概就是這麼個原理,那這個 ERP 難道也是出現了 快進快出 的現象嗎?是不是我們可以挖一下哈,方法就是統計一下 無根物件 佔託管堆的一個 百分比,使用 !heapstat -iu 命令。


0:000> !heapstat -iu
Heap             Gen0         Gen1         Gen2          LOH          POH
Heap0       124129016    105671896      5371520      4063704       795560
Heap1       100102816    109941488      4421800      4719072       452904
Heap2       144913984    105093616      7285888      4325960      1917928
Heap3       125996096    109904696      8612112      4194608       425976
Heap4       124567184    102635432      7450536      3670432       393400
Heap5       122508864    104438848     12821224      4076136       458616
Heap6       124459664    120851840      5901680      6615192       311352
Heap7       131309360     97620536      8585720      8660720       602072
Total       997986984    856158352     60450480     40325824      5357808

Free space:                                                               Percentage
Heap0          426616      2332200         3032       393520          264 SOH:  1%
Heap1          380752      2403984         1768       131208          320 SOH:  1%
Heap2          484008      2306424         4328          344          616 SOH:  1%
Heap3          436888      2403000         1168          184           24 SOH:  1%
Heap4          446192      2266944         1936       393512           24 SOH:  1%
Heap5          444176      2302824         5232       131440           24 SOH:  1%
Heap6          429048      2648592         9104       884800           24 SOH:  1%
Heap7          441216      2144136         3272       168992           80 SOH:  1%
Total         3488896     18808104        29840      2104000         1376

Unrooted objects:                                            Percentage
Heap0       121561744    103338800        56592      3145872            0 SOH: 95%
Heap1        99418536    107524544        19800      4456760            0 SOH: 96%
Heap2       144081016    102786776        36920      4325616            0 SOH: 95%
Heap3       124591744    107491216        23832      4194424            0 SOH: 94%
Heap4       123946896    100368288        10400      3145824           88 SOH: 95%
Heap5       121457024    102135728        24032      3539136            0 SOH: 93%
Heap6       123739008    118202552         2288      5243072            0 SOH: 96%
Heap7       130593408     95460992          736      3539136            0 SOH: 95%
Total       989389376    837308896       174600     31589840           88

從卦中看,當前 Unrooted objects 區域佔 SOH 的比率都是在 93% 以上,就是說託管堆上幾乎都是 無根物件,這也驗證了 快進快出 的現象,接下來的問題就是挖下是什麼導致了 快進快出

3. 什麼導致了 快進快出

要找到這個答案需要到託管堆看一下,是否有超出預期的物件分配,使用 !dumpheap -stat 即可。


0:000> !dumpheap -stat
Statistics:
              MT    Count    TotalSize Class Name
            ...
00007ff7bf388fa8  1300147     31203528 System.DateTime
00007ff7c04db260      124     32312064 xxx.UDP_Retention[]
00007ff7bfeb2c00  1239416    317290496 xxx.UDP_Retention
00007ff7c00cfe88 12997664    415925248 FreeSql.Internal.Utils+RowInfo
00007ff7bf107a90 21175792    909769558 System.String
Total 40777517 objects

從卦中看: FreeSql.Internal.Utils+RowInfo 高達 1300w ,同時 xxx.UDP_Retention 物件也高達 123wFreeSql 相信國內很多開發者都知道,是一個資料存取的SDK,很顯然這個 ERP 應該從資料庫中讀取了不少資料, FreeSql 在內部為了做對映生成了非常多的臨時物件。

那現在的突破點在哪裡呢?就是尋找問題 SQL,找下和類名同名的表名 UDP_Retention 即可,寫個指令碼查一下就好了,結果發現有不少這樣的 sql,輸出如下:


SELECT *
FROM 
    (SELECT *
    FROM UDP_Retention with(nolock)
    WHERE ID NOT IN 
        (SELECT xxxId
        FROM UDP_Retention_Pxxxx with(nolock)) ) a 

那這條 sql 會撈出多少資料呢?可以觀察下 UDP_Retention[] 即可,然後稍微過濾一下。


0:000> !DumpHeap -mt 00007ff7c04db260 -min 0n1048576
         Address               MT     Size
00000244c3b71188 00007ff7c04db260  1048600     
00000244c3c711c0 00007ff7c04db260  1048600     
00000244d3bd1120 00007ff7c04db260  1048600     
00000244e3a710e0 00007ff7c04db260  1048600     
00000244e3cb1230 00007ff7c04db260  1048600     
00000244f3a11070 00007ff7c04db260  1048600     
00000244f3b910e0 00007ff7c04db260  1048600     
00000244f3c91118 00007ff7c04db260  1048600     
0000024503a91118 00007ff7c04db260  1048600     
0000024503b91150 00007ff7c04db260  1048600     
0000024513c74250 00007ff7c04db260  1048600     
00000245239c90c8 00007ff7c04db260  1048600     
0000024523ac9100 00007ff7c04db260  1048600     
0000024523de0048 00007ff7c04db260  1048600     
0000024523ee0080 00007ff7c04db260  1048600     
00000245339d0f68 00007ff7c04db260  1048600     
0000024534013668 00007ff7c04db260  1048600     

Statistics:
              MT    Count    TotalSize Class Name
00007ff7c04db260       17     17826200 xxx.UDP_Retention[]
Total 17 objects

0:000> !DumpObj /d 0000024534013668
Name:        xxx.UDP_Retention[]
MethodTable: 00007ff7c04db260
EEClass:     00007ff7bf0467c8
Size:        1048600(0x100018) bytes
Array:       Rank 1, Number of elements 131072, Type CLASS (Print Array)
Fields:
None

從卦中資訊看, 大概有 17 個 13w 的記錄,說明這個sql會一次性撈取 10w+ ,用完之後即刻釋放,也就表示為什麼 SOH 會佔用 93% 以上的無根物件。

三:總結

總的來說,這次記憶體暴漲是因為程式出現了分配的 快進快出 現象導致的,如果你不想管也可以不用管,GC 在下次發兵時會一舉殲滅,如果要做優化的話,需要優化下 sql,不要一次性查詢出 10w+ 的資料,不過說實話,FreeSql 在對映方面最好也要做些優化,畢竟產生了 1300w 的臨時物件,雖然不是它的錯。

圖片名稱