一:背景 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 Size
和 GC 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
對象也高達 123w
, FreeSql
相信國內很多開發者都知道,是一個數據訪問的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
的臨時對象,雖然不是它的錯。