记一次 .NET 某外贸ERP 内存暴涨分析

2023-07-29,,

一:背景

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 Committed 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 的临时对象,虽然不是它的错。

记一次 .NET 某外贸ERP 内存暴涨分析的相关教程结束。

《记一次 .NET 某外贸ERP 内存暴涨分析.doc》

下载本文的Word格式文档,以方便收藏与打印。