記一次 .NET 某外貿ERP 內存暴漲分析

opendotnet 發佈 2024-01-01T14:58:21.065699+00:00

一:背景 1. 講故事上周有位朋友找到我,說他的 API 被多次調用後出現了內存暴漲,讓我幫忙看下是怎麼回事?看樣子是有些擔心,但也不是特別擔心,那既然找到我,就給他分析一下吧。二:WinDbg 分析 1.

一:背景

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的臨時對象,雖然不是它的錯。

關鍵字: