记一次 .NET 某电力系统内存暴涨分析

一：背景

1. 讲故事

前些天有位朋友找到我，说他生产上的程序有内存暴涨情况，让我帮忙看下怎么回事，最简单粗暴的方法就是让朋友在内存暴涨的时候抓一个dump下来，看一看大概就知道咋回事了。

二：Windbg 分析

1. 到底是谁吃了内存

这个问题说的再多也不为过，一定要看清楚这个程序是如何个性化发展的，可以使用 !address -summary 命令。


0:000> !address -summary

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                                    255     7dfb`064e1000 ( 125.981 TB)           98.42%
<unknown>                               529      204`d53ac000 (   2.019 TB)  99.97%    1.58%
Heap                                    889        0`170f0000 ( 368.938 MB)   0.02%    0.00%
Image                                  1214        0`07a9a000 ( 122.602 MB)   0.01%    0.00%
Stack                                   192        0`05980000 (  89.500 MB)   0.00%    0.00%
Other                                    10        0`001d8000 (   1.844 MB)   0.00%    0.00%
TEB                                      64        0`00080000 ( 512.000 kB)   0.00%    0.00%
PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                255     7dfb`064e1000 ( 125.981 TB)           98.42%
MEM_RESERVE                             709      204`43eab000 (   2.017 TB)  99.86%    1.58%
MEM_COMMIT                             2190        0`b5c64000 (   2.840 GB)   0.14%    0.00%

从卦象看进程内存也才 2.84G，严格来说也不算多，可能朋友抓的有点心急，从上面的 unknown 指标看大概率是托管堆的暴涨，继续使用 !eeheap -gc 观察下托管堆。


0:000> !eeheap -gc

========================================
Number of GC Heaps: 4
----------------------------------------
Heap 0 (000001d0adf50a20)
generation 0 starts at 1d0b3fad350
generation 1 starts at 1d0b3f9be88
generation 2 starts at 1d0ae5d1000
ephemeral segment allocation context: none
Small object heap
         segment            begin        allocated        committed allocated size          committed size         
    01d0ae5d0000     01d0ae5d1000     01d0b4046258     01d0b48ac000 0x5a75258 (94851672)    0x62dc000 (103661568)  
Large object heap starts at 1d4ae5d1000
         segment            begin        allocated        committed allocated size          committed size         
    01d4ae5d0000     01d4ae5d1000     01d4b6d0c4e8     01d4b6d2d000 0x873b4e8 (141800680)   0x875d000 (141938688)  
Pinned object heap starts at 1d4ee5d1000
         segment            begin        allocated        committed allocated size          committed size         
    01d4ee5d0000     01d4ee5d1000     01d4ee5e4f08     01d4ee5f2000 0x13f08 (81672)         0x22000 (139264)       
------------------------------
...
Heap 3 (000001d0ae4fd000)
generation 0 starts at 1d3b26929e0
generation 1 starts at 1d3b2687ad8
generation 2 starts at 1d3ae5d1000
ephemeral segment allocation context: none
Small object heap
         segment            begin        allocated        committed allocated size          committed size         
    01d3ae5d0000     01d3ae5d1000     01d4179a5980     01d418021000 0x693d4980 (1765624192) 0x69a51000 (1772425216)
Large object heap starts at 1d4de5d1000
         segment            begin        allocated        committed allocated size          committed size         
    01d4de5d0000     01d4de5d1000     01d4df8836d8     01d4df884000 0x12b26d8 (19605208)    0x12b4000 (19611648)   
Pinned object heap starts at 1d51e5d1000
         segment            begin        allocated        committed allocated size          committed size         
    01d51e5d0000     01d51e5d1000     01d51e5dd7e0     01d51e5e2000 0xc7e0 (51168)          0x12000 (73728)        
------------------------------
GC Allocated Heap Size:    Size: 0x8a6b9060 (2322305120) bytes.
GC Committed Heap Size:    Size: 0x8c6b1000 (2355826688) bytes.

从GC堆看果然是托管层的问题，继续使用 !dumpheap -stat 观察下托管堆的现状，看看哪一位是罪魁祸首。


0:000> !dumpheap -stat
Statistics:
          MT     Count     TotalSize Class Name
...
7fff32e81db8        43    68,801,032 SmartMeter.Mem.TerminalInfo[]
7fff329f7470   200,000   110,400,000 SmartMeter.Model.MeterInfo_Model
7fff3227d708 2,285,392   116,193,998 System.String
01d0ae46b350       543 1,857,281,320 Free
Total 3,947,969 objects, 2,314,533,332 bytes

Fragmented blocks larger than 0.5 MB:
         Address           Size      Followed By
    01d0ae935870        723,384     01d0ae9e6228 System.SByte[]
    01d1b41d3cd0     23,081,616     01d1b57d6f60 System.Byte[]
    01d3b274eb40  1,696,943,656     01d4179a3968 System.Byte[]

这卦不看不知道，一看吓一跳，这2.3G的内存，居然被一个 1.69G 的Free给侵吞了，不信的话可以用 !do 验证下。


0:000> !do 01d3b274eb40
Free Object
Size:        1696943656(0x65254e28) bytes

2. 为什么会有这么大的Free

这是一个值得思考的问题，也决定着我们下一步分析的方向，接下来就是看下这个 free 的落脚点以及周围对象的分布情况，可以使用 !gcwhere 观察。


0:000> !gcwhere 01d3b274eb40
Address          Heap   Segment          Generation Allocated               Committed               Reserved               
01d3b274eb40     3      01d3ae5d0000     0          1d3ae5d1000-1d4179a5980 1d3ae5d0000-1d418021000 1d418021000-1d4ae5d0000

0:000> !dumpheap -segment 1d3ae5d0000
    ...
    01d3b274e948     7fff32468658             96 
    01d3b274e9a8     7fff3227d708             28 
    01d3b274e9c8     7fff3227d708             28 
    01d3b274e9e8     7fff32d0c8d8             80 
    01d3b274ea38     7fff3227d708             96 
    01d3b274ea98     7fff32d0aa38             40 
    01d3b274eac0     01d0ae46b350            128 Free
    01d3b274eb40     01d0ae46b350  1,696,943,656 Free
    01d4179a3968     7fff323e1638          8,216

从卦象看挺遗憾的，如果 Free 落在segment的最后一个位置，那么 segment 就会 uncommitted 进而内存就下去了，可偏偏最后一个位置是 8216byte 的对象占据着，阻止了内存的回收，有经验的朋友可能知道，这个对象非富即贵，大概率是被 pinned 了，可以用 !gcroot 观察下。


0:000> !gcroot 01d4179a3968
HandleTable:
    000001d0ae3927f8 (async pinned handle)
          -> 01d3b26706f0     System.Threading.OverlappedData 
          -> 01d4179a3968     System.Byte[] 

Found 1 unique roots.

0:000> !dumpobj /d 1d4179a3968
Name:        System.Byte[]
MethodTable: 00007fff323e1638
EEClass:     00007fff323e15b8
Tracked Type: false
Size:        8216(0x2018) bytes
Array:       Rank 1, Number of elements 8192, Type Byte (Print Array)
Content:     ............L.o.g.\.2.0.2.3.0...
Fields:
None

从上面的 async pinned handle 来看是一个文件监控的回调函数，到这里就可以从表象解释：是这个 8216 的对象导致的内存无法回收。

3. 真的要 8216 来担责吗

如果你真的要让 8216 来担责，那真的只看到了表象，内存的突然暴涨回不去只是恰好遇到了 8216 的阻止，但它不是本质原因，真正要考虑的是为什么GC回收后会产生这么大一个单独 Free，其实隐喻了当前程序出现过短时的 大对象分配，对，就是这个词。

接下来的问题是如何找到这个 大对象分配 呢？最好的方法就是用 perfview 的 .NET SampAlloc 去洞察，如果非要用 WinDbg 的话那就只能看看 Free 生前是什么，或许能寻找到答案，可以借助 .writemem 命令观察。


0:000> !do 01d3b274eb40
Free Object
Size:        1696943656(0x65254e28) bytes

0:000> .writemem D:\testdump\1.txt 01d3b274eb40 L?0x65254e28
Writing 65254e28 bytes................

从卦中数据看有大量的计费信息，看样子又是从数据库中短时的捞取了大批量数据在托管堆上折腾导致的，知道了本质原因，解决办法就比较简单了，通常有两种做法。

修改 GC 模式，改成 Workstation。
大批量数据改成小步快跑

三：总结

这起内存暴涨事故，表象上是 8216 的阻挡导致了内存无法被uncommitted所致，本质上还是归于托管堆的 内存黑洞 现象。