記一次 .NET 某餐飲小程式 記憶體暴漲分析

一線碼農發表於2023-09-21

一:背景

1. 講故事

前些天有位朋友找到我,說他的程式記憶體異常高,用 vs診斷工具 載入時間又太久,讓我幫忙看一下到底咋回事,截圖如下:

確實,如果dump檔案超過 10G 之後,市面上那些視覺化工具分析起來會讓你崩潰的,除了時間久之外這些工具大多也不是用懶載入的方式,比如 dotmemory 會把資料全部灌入記憶體,針對這種dump,你沒個32G記憶體就不要分析了,這也是 windbg 在此類場景下的用武之地。

閒話不多說,朋友的dump到了,趕緊分析一波。

2. 到底是誰吃了記憶體

還是那句話,用 !address -summary 看下是託管記憶體還是非託管記憶體的問題。


0:000> !address -summary

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                                    366     7dbf`3e6cb000 ( 125.747 TB)           98.24%
<unknown>                              5970      240`99b78000 (   2.252 TB)  99.97%    1.76%
Stack                                   159        0`136a0000 ( 310.625 MB)   0.01%    0.00%
Image                                  1943        0`0a2e8000 ( 162.906 MB)   0.01%    0.00%
Heap                                     89        0`0a1e0000 ( 161.875 MB)   0.01%    0.00%
Other                                    12        0`001da000 (   1.852 MB)   0.00%    0.00%
TEB                                      53        0`0006a000 ( 424.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                                366     7dbf`3e6cb000 ( 125.747 TB)           98.24%
MEM_RESERVE                             608      23d`fda87000 (   2.242 TB)  99.52%    1.75%
MEM_COMMIT                             7619        2`c3e9e000 (  11.061 GB)   0.48%    0.01%

從卦中看 ntheap=161M,看樣子是託管堆的問題了,繼續使用 !eeheap -gc 看下託管堆。


0:000> !eeheap -gc
Number of GC Heaps: 8
------------------------------
Heap 0 (00000277134AD330)
Small object heap
         segment             begin         allocated         committed    allocated size    committed size
generation 0:
000002B727864BB0  00000279A4000020  00000279A43FFFD0  00000279A4400000  0x3fffb0(4194224)  0x400000(4194304)
000002B727869500  00000279BD800020  00000279BDBFFF70  00000279BDC00000  0x3fff50(4194128)  0x400000(4194304)
...
000002B727852950  000002793F000020  000002793F3FFFA0  000002793F400000  0x3fff80(4194176)  0x400000(4194304)
000002B727853080  0000027941800020  00000279419B6FA0  00000279419C1000  0x1b6f80(1798016)  0x1c1000(1839104)
Frozen object heap
         segment             begin         allocated         committed    allocated size    committed size
Large object heap
         segment             begin         allocated         committed    allocated size    committed size
000002B7277F53C0  0000027737800020  00000277378580A8  0000027737879000  0x58088(360584)  0x79000(495616)
Pinned object heap
         segment             begin         allocated         committed    allocated size    committed size
000002B7277F1480  0000027721800020  0000027721833A80  0000027721841000  0x33a60(211552)  0x41000(266240)
Allocated Heap Size:       Size: 0x4e17d578 (1310184824) bytes.
Committed Heap Size:       Size: 0x4effd000 (1325387776) bytes.
------------------------------
GC Allocated Heap Size:    Size: 0x280020b18 (10737552152) bytes.
GC Committed Heap Size:    Size: 0x28835f000 (10875170816) bytes.

我去,一下子刷了好幾屏,從卦中可以看到記憶體佔用高達 10G+, 往細處看都是 Small object heap 給吃掉了,既然是SOH堆,看樣子都是熱和著呢,潛臺詞就是他們的根很可能在執行緒棧裡,經驗之談哈。

有了這些猜測,接下來觀察下託管堆,看看誰的佔比最大,使用 !dumpheap -stat 即可。


0:000> !dumpheap -stat
Statistics:
              MT    Count    TotalSize Class Name
...
00007ffc41beaa68     4894      1732200 System.Object[]
00007ffc41fc0468     7058      2368001 System.Byte[]
00007ffc41dbf7b8    24209      2517736 System.Reflection.RuntimeMethodInfo
00007ffc43429178        3    536870984 xxxLogEntity[]
000002771340e900 46106634   1866065488      Free
00007ffc41c6fd10 55920839   2125832534 System.String
00007ffc42ddc0b8 50634021   6076082520 xxxxxxxLogEntity

不看不知道,一看嚇一跳,這 xxxxxxLogEntity 物件居然高達 5063w,佔據著 6G 的記憶體,那為什麼會有這麼多的物件呢?用 !gcroot 抽幾個看看便知。


0:000> !dumpheap -mt 00007ffc42ddc0b8
         Address               MT     Size
00000279a405b010 00007ffc42ddc0b8      120    
...
00000279c31648a0 00007ffc42ddc0b8      120     
00000279c3164968 00007ffc42ddc0b8      120     
00000279c3164a30 00007ffc42ddc0b8      120     
00000279c3164af8 00007ffc42ddc0b8      120     
00000279c3164bc0 00007ffc42ddc0b8      120     
00000279c3164c88 00007ffc42ddc0b8      120     
00000279c3164d50 00007ffc42ddc0b8      120     

0:000> !gcroot 00000279c3164d50
Thread a65c:
    0000009BA592BD80 00007FFC458F99C8 xxx+<xxx>d__14.MoveNext()
        rbx: 
            ->  0000027723C9B8F8 System.Collections.Generic.List`1[[xxx]]
            ->  00000278F2000040 xxxxxxLogEntity[]
            ->  00000279C3164D50 xxxxxxLogEntity

Found 1 unique roots (run '!gcroot -all' to see all roots).

0:000> !do 0000027723C9B8F8
Name:        System.Collections.Generic.List`1[[xxx]]
MethodTable: 00007ffc43024ec0
EEClass:     00007ffc41d956b0
Tracked Type: false
Size:        32(0x20) bytes
File:        C:\Program Files\dotnet\shared\Microsoft.NETCore.App\7.0.4\System.Private.CoreLib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ffc420fac80  4002149        8     System.__Canon[]  0 instance 00000278f2000040 _items
00007ffc41bee8d0  400214a       10         System.Int32  1 instance         50634020 _size
00007ffc41bee8d0  400214b       14         System.Int32  1 instance         50634020 _version
00007ffc420fac80  400214c        8     System.__Canon[]  0   static dynamic statics NYI 

從卦象中可以看到,這 5063w 個物件都被這個 list 持有,更有意思的是果然被我猜到了,這個list的根在 a65c 這個執行緒裡,接下來的問題是這個執行緒正在做什麼?

3. a65c 執行緒正在做什麼

要想看這個神秘執行緒正在做什麼,可以用 ~ 命令切過去看看執行緒棧,看看哪一個方法在引用這個 list。


0:036> ~~[a65c]s
00007ffc`451fefe6 482bc2          sub     rax,rdx

0:036> !clrstack -a
OS Thread Id: 0xa65c (36)
0000009BA592BD80 00007ffc458f99c8 xxxxBase+d__14.MoveNext()
    PARAMETERS:
        this (<CLR reg>) = 0x0000027723c515b8
    LOCALS:
        <no data>
        <CLR reg> = 0x00000277287cd6d8
        <no data>
        <no data>
        ...
        <no data>
        <CLR reg> = 0x0000027723c9b8f8
        <no data>

找到了是 xxxxBase+d__14.MoveNext 方法之後,接下來就需要仔細研讀程式碼,終於找到了,寫了一個死迴圈,真是無語了,截圖如下:

終於真相大白,程式設計師誤以為使用 dateTime.AddDays(1.0); 就可以修改 dateTime 的時間,犯了一個低階錯誤呀。

改成 dateTime=dateTime.AddDays(1.0); 即可。

三:總結

這次記憶體暴漲把生產伺服器弄崩了,就是因為這麼個 低階錯誤導致實屬不應該,本以為程式設計師不會寫出什麼死迴圈,還真的遇到了,提高開發人員的程式碼敏感性迫在眉睫。

圖片名稱

相關文章