記一次 .NET 某三甲醫院HIS系統 記憶體暴漲分析

一線碼農發表於2021-05-31
記憶體

一：背景

1. 講故事

前幾天有位朋友加wx說他的程式遭遇了記憶體暴漲，求助如何分析？

和這位朋友聊下來，這個dump也是取自一個HIS系統，如朋友所說我這真的是和醫院槓上了???，這樣也好，給自己攢點資源???，好了，不扯了，上windbg說話。

二： windbg 分析

1. 託管還是非託管？

既然是記憶體暴漲，那就看看當前程式的 commit 記憶體有多大？


0:000> !address -summary

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                174     7ffe`baac0000 ( 127.995 TB)          100.00%
MEM_COMMIT                             1153        1`33bd3000 (   4.808 GB)  94.59%    0.00%
MEM_RESERVE                             221        0`1195d000 ( 281.363 MB)   5.41%    0.00%

可以看出大概佔了 4.8G,接下來再看看託管堆記憶體。


0:000> !eeheap -gc
Number of GC Heaps: 1
generation 0 starts at 0x00000207a4fc48c8
generation 1 starts at 0x00000207a3dc3138
generation 2 starts at 0x0000020697fc1000
ephemeral segment allocation context: none
------------------------------
GC Heap Size:            Size: 0x1241b3858 (4900730968) bytes.

從最後一行可以看出託管堆佔用 4900730968/1024/1024/1024=4.5G，兩個指標一比對，原來是託管記憶體出問題了，這下好辦了。。。

2. 檢視託管堆

既然記憶體是被託管堆吃掉了，那就看看託管堆上到底都有些什麼東西？？？


0:000> !dumpheap -stat
Statistics:
              MT    Count    TotalSize Class Name
...
00007ffd00397b98  1065873    102323808 System.Data.DataRow
00000206978b8250  1507805    223310768      Free
00007ffd20d216b8  4668930    364025578 System.String
00007ffd20d22aa8      797    403971664 System.String[]
00007ffd20d193d0   406282   3399800382 System.Byte[]
Total 9442152 objects

不看不知道，一看嚇一跳，System.Byte[] 差不多佔用了 3.3 G 記憶體，也就是說 gc 堆差不多都被它吃掉了，根據經驗肯定是有個什麼大物件，那接下來怎麼分析呢？除了用指令碼對 byte[] 進行暴力分組統計之外，純人肉還有其他的技巧嗎? 當然有，可以用 !heapstat 觀察下這些物件在託管堆上的代資訊。


0:000> !heapstat
Heap             Gen0         Gen1         Gen2          LOH
Heap0         2252000     18880400   3968704192    910894376

Free space:                                                 Percentage
Heap0           43128       770160    185203264     39849984SOH:  4% LOH:  4%

從圖中可以看出，當前的大頭在 Gen2 上，接下來可以用 eeheap -gc 去找 Gen2 的段地址區間，從而最小化的顯示heap上內容。


0:000> !eeheap -gc
Number of GC Heaps: 1
generation 0 starts at 0x00000207a4fc48c8
generation 1 starts at 0x00000207a3dc3138
generation 2 starts at 0x0000020697fc1000
ephemeral segment allocation context: none
         segment             begin         allocated              size
0000020697fc0000  0000020697fc1000  00000206a7fbec48  0xfffdc48(268426312)
00000206bbeb0000  00000206bbeb1000  00000206cbeaef50  0xfffdf50(268427088)
00000206ccc40000  00000206ccc41000  00000206dcc3f668  0xfffe668(268428904)
00000206dcc40000  00000206dcc41000  00000206ecc3f098  0xfffe098(268427416)
0000020680000000  0000020680001000  000002068ffff8c0  0xfffe8c0(268429504)
00000206ff4d0000  00000206ff4d1000  000002070f4cf588  0xfffe588(268428680)
000002070f4d0000  000002070f4d1000  000002071f4cf9f0  0xfffe9f0(268429808)
000002071f4d0000  000002071f4d1000  000002072f4cfef0  0xfffeef0(268431088)
000002072f4d0000  000002072f4d1000  000002073f4cf748  0xfffe748(268429128)
000002073f4d0000  000002073f4d1000  000002074f4ce900  0xfffd900(268425472)
00000207574d0000  00000207574d1000  00000207674cfe70  0xfffee70(268430960)
00000207674d0000  00000207674d1000  00000207774ceaf8  0xfffdaf8(268425976)
00000207774d0000  00000207774d1000  00000207874cf270  0xfffe270(268427888)
00000207874d0000  00000207874d1000  00000207974cf7a8  0xfffe7a8(268429224)
00000207974d0000  00000207974d1000  00000207a51ea5a8  0xdd195a8(231839144)

一般來說，第一個 segment 是給 gen0 + gen1 的，後續的 segment 就是 gen2，接下來我就選 segment： 00000206dcc41000 - 00000206ecc3f098 ，然後使用 !dumpheap 匯出該區間的所有物件。


0:000> !dumpheap -stat 00000206dcc41000 00000206ecc3f098
Statistics:
              MT    Count    TotalSize Class Name
00007ffd00397b98   191803     18413088 System.Data.DataRow
00007ffd20d216b8   662179     37834152 System.String
00007ffd20d193d0    23115    187896401 System.Byte[]

從這個記憶體段上看，Byte[] 有 2.3w 個，還不算多，全部dump出來看看有什麼特徵。


0:000> !dumpheap -mt 00007ffd20d193d0 00000206dcc41000 00000206ecc3f098
         Address               MT     Size
00000206dcc410e8 00007ffd20d193d0     8232     
00000206dcc43588 00007ffd20d193d0     8232     
00000206dcc45a48 00007ffd20d193d0     8232     
00000206dcc47d78 00007ffd20d193d0     8232     
00000206dcc4a028 00007ffd20d193d0     8232     
00000206dcc4c4b0 00007ffd20d193d0     8232     
00000206dcc4eb08 00007ffd20d193d0     8232     
00000206dcc50e88 00007ffd20d193d0     8232     
00000206dcc535b0 00007ffd20d193d0     8232     
00000206dcc575d8 00007ffd20d193d0     8232     
00000206dcc5a5a8 00007ffd20d193d0     8232     
00000206dcc5cbf8 00007ffd20d193d0     8232     
00000206dcc5eef8 00007ffd20d193d0     8232     
00000206dcc611f8 00007ffd20d193d0     8232     
00000206dcc634e8 00007ffd20d193d0     8232     
00000206dcc657f0 00007ffd20d193d0     8232     
00000206dcc67af8 00007ffd20d193d0     8232     
00000206dcc69e00 00007ffd20d193d0     8232   
...

我去，99% 都是 8232byte，原來都是些 8k 的byte陣列，那到底誰在使用它，用 !gcroot 查一下引用根。


0:000> !gcroot 00000206dcc410e8
Thread 8c1c:
        rsi: 
            ->  00000206983d5730 System.ServiceProcess.ServiceBase[]
                ...
            ->  000002069dcb6d38 OracleInternal.ConnectionPool.OraclePool
                ...
            ->  000002069dc949c0 OracleInternal.TTC.OraBufReader
            ->  000002069dc94a70 System.Collections.Generic.List`1[[OracleInternal.Network.OraBuf, Oracle.ManagedDataAccess]]
            ->  00000206ab8c2200 OracleInternal.Network.OraBuf[]
            ->  00000206dcc41018 OracleInternal.Network.OraBuf
            ->  00000206dcc410e8 System.Byte[]

從引用鏈來看，貌似是被 OracleInternal.Network.OraBuf[] 持有著，這就很疑惑了，難道是 Oracle Sdk 出的bug把記憶體給搞崩了？ 好奇心來了，看一下元素個數和size各是多少？


0:000> !do 00000206ab8c2200
Name:        OracleInternal.Network.OraBuf[]
MethodTable: 00007ffcc7833c68
EEClass:     00007ffd20757728
Size:        4194328(0x400018) bytes
Array:       Rank 1, Number of elements 524288, Type CLASS (Print Array)
Fields:
None

0:000> !objsize 00000206ab8c2200
sizeof(00000206ab8c2200) = -1086824024 (0xbf3861a8) bytes (OracleInternal.Network.OraBuf[])

當前陣列有 52w ，totalsize直接負數了?。

3. 尋找問題程式碼

知道現象之後，接下來用 ILSpy 把 Oracle SDK 反編譯看看，最終一比對，如下圖所示：

原來m_tempOBList是記憶體暴漲的罪魁禍首，這就很尷尬了，它為什麼會暴漲？ 為什麼不釋放？ 由於我對 Oracle 也不熟悉，只能求助於神奇的 StackOverflow，我去，還真有天涯淪落人，Huge managed memory allocation when reading (iterating) data with DbDataReader

大概是說這種現象是 Oracle SDK 在讀取 Clob 型別的欄位有一個bug，解決辦法也很簡單，用完後就釋放，詳情參見如下圖：

4. 尋找真相

既然帖子上是說讀取 Clob 型別出的問題，那就把所有執行緒棧都調出來，看看此時的執行緒棧中是否有 Clob 的蹤影？

從執行緒棧上看，程式碼是通過 ToDataTable 方法將 IDataReader 轉成 DataTable，在轉換過程中讀取了大欄位，自然就有了 GetCompleteClobData，也就是說完美命中帖子所說，為了讓結論更準確，我就去挖一下當前的 DataReader 已經讀了多少行了？


0:028> !clrstack -a
OS Thread Id: 0xbab0 (28)
000000e78ef7d520 00007ffd00724458 System.Data.DataTable.Load(System.Data.IDataReader, System.Data.LoadOption, System.Data.FillErrorEventHandler)
    PARAMETERS:
        this = <no data>
        reader (<CLR reg>) = 0x00000206a530ac20
        loadOption = <no data>
        errorHandler = <no data>
0:028> !do 0x00000206a530ac20
Name:        Oracle.ManagedDataAccess.Client.OracleDataReader
MethodTable: 00007ffcc7933b10
EEClass:     00007ffcc78efd30
Size:        256(0x100) bytes
File:        D:\xxx.dll
Fields:
00007ffd20d23e98  4000337       d0         System.Int32  1 instance          1061652 m_RowNumber

從 m_RowNumber 看，已經讀取了 106w 行，一次性讀取100w+的記錄不常見，如果還有大欄位的話，那也是??了。

三：總結

綜合來看這次事故是因為一次性讀取含有大欄位的百萬級資料到DataTable引發，解決方案很簡單，自己通過 for 讀取 DataReader，在處理完 OracleClob 型別之後馬上釋放，參考帖子程式碼：


var item = oracleDataReader.GetOracleValue(columnIndex);

if (item is OracleClob clob)
{
    if (clob != null)
    {
        // use clob.Value ...

        clob.Close();
    }
}

更多高質量乾貨：參見我的 GitHub: dotnetfly

圖片名稱

相關文章