• API 被多次调用后出现内存暴涨的原因分析
  • 发布于 2个月前
  • 357 热度
    0 评论
一:背景
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[] 即可,然后稍微过滤一下。
// 堆代码 duidaima.com
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 的临时对象,虽然不是它的错。
用户评论