说来也奇怪,最近分析了好几例内存暴涨事故,这不又来了,哈哈,今天再给大家带来一份非托管内存泄露导致的程序生产故障,而且是部署在Linux上.NET程序。
前些天有位朋友找到我,自己有一定的分析能力,发现程序是非托管内存泄露,但能力有限暂时也不知道怎么弄,让我帮忙看下,把dump也丢给我了,既然dump有了,那就开始分析吧。
虽然朋友说了是非托管内存泄露,但我们还是要相信数据,使用 !maddress 观察即可。
0:000> !maddress +-------------------------------------------------------------------------+ | Memory Type | Count | Size | Size (bytes) | +-------------------------------------------------------------------------+ | PAGE_READWRITE | 2,465 | 3.64gb | 3,913,596,928 | | GCHeap | 9 | 1.45gb | 1,557,557,248 | | Stack | 63 | 972.26mb | 1,019,490,304 | | Image | 1,413 | 287.81mb | 301,786,112 | | HighFrequencyHeap | 1,722 | 107.54mb | 112,758,784 | | LowFrequencyHeap | 903 | 66.32mb | 69,545,984 | | LoaderCodeHeap | 35 | 61.00mb | 63,963,136 | | HostCodeHeap | 85 | 19.97mb | 20,942,848 | | ResolveHeap | 3 | 1.09mb | 1,142,784 | | IndirectionCellHeap | 9 | 536.00kb | 548,864 | | StubHeap | 8 | 460.00kb | 471,040 | | DispatchHeap | 2 | 452.00kb | 462,848 | | CacheEntryHeap | 7 | 420.00kb | 430,080 | | LookupHeap | 5 | 272.00kb | 278,528 | | PAGE_READONLY | 125 | 263.00kb | 269,312 | | PAGE_EXECUTE_WRITECOPY | 6 | 232.00kb | 237,568 | | PAGE_EXECUTE_READ | 2 | 8.00kb | 8,192 | +-------------------------------------------------------------------------+ | [TOTAL] | 6,862 | 6.58gb | 7,063,490,560 | +-------------------------------------------------------------------------+ 从卦中我们看到程序总计吃了 6.58G 内存,其中 PAGE_READWRITE = 3.64G,很显然这是赤裸裸的非托管内存泄露,说实话Linux上的非托管内存泄露不是很好弄,接下来我们的研究方向在哪里呢?
在如今AI横行的时代,可以用一个小技巧,那就是用AI将 2465个 PAGE_READWRITE 做一个 groupby 操作,寻找size的特征,这里取 top5 的记录,截图如下:

从卦中可以清晰的看到,主体上是被 50~200MB 这个区间吃掉了,接下来我们随便挑选几个观察其中内容,截图如下:

从卦中可以看到大量的 lambda_methodxxx 的字样,看起来和动态代码生成有关系,但还不是那么清晰。
不管怎么说,数字这么大了,冥冥之中应该是一种失控,熟悉C# 的朋友应该知道这个应该是 C# 通过 DynamicMethod 类似的机制动态生成的方法,所以我们的接下来的注意力应该投向托管堆了,使用 !dumpheap -stat 观察托管堆。
0:000> !dumpheap -stat...7f6cee5e6360 105,28810,949,952 System.Reflection.RuntimeMethodInfo7f6cf0943da8 81,26111,701,584 System.Reflection.Emit.DynamicILGenerator7f6cfc273e40 1,42811,732,448 IndexItem[]7f6cf883b510 13,18912,785,440 System.Collections.Concurrent.ConcurrentDictionary<System.String, System.Object>+Node[]7f6cf9c3aaa0 132,06313,734,552 OracleInternal.Common.ColumnDescribeInfo7f6cfa1f54b0 20,42416,314,756 Oracle.ManagedDataAccess.Client.OracleParameterStatus[]7f6cf97f7cb8 55,84428,145,376 Oracle.ManagedDataAccess.Client.OracleConnection7f6ceed94548 21,31032,195,096 System.Byte[][]7f6cedb852a8 1,445,51634,692,384 System.Object7f6cff21ea98 728,16240,777,072 SkiaSharp.SKString7f6cf561ca90 1,343,65042,996,800 Microsoft.Win32.SafeHandles.SafeEvpCipherCtxHandle7f6cedb8b110 144,68554,552,728 System.Object[]7f6cf0cd1110 1,878,51160,112,352 Microsoft.Win32.SafeHandles.SafeWaitHandle55ad23d21ab0 58,64870,742,904 Free7f6cedc38080 141,177100,202,360 System.Int32[]7f6cedc3d2e0 2,827,739188,196,546 System.String7f6cee5ea3a0 3,787,714280,567,631 System.Byte[]Total 18,171,140 objects, 1,533,484,720 bytesFragmented blocks larger than 0.5 MB: Address Size Followed By7f6a1d47cb18 3,359,3447f6a1d7b0d88 System.Byte[]7f6a1d81c080 1,151,4087f6a1d935230 System.IO.Compression.ZLibNative+ZLibStreamHandle看到卦中的 DynamicILGenerator=10.5w 的时候,猜想再次被印证,看样子非托管内存中都是它投放的,接下来观察 DynamicILGenerator 的引用根看看到底咋回事。
0:000> !dumpheap -mt 7f6cf0943da8 Address MT Size ...7f6cc7f7a3f0 7f6cf0943da8 1447f6cc7f81168 7f6cf0943da8 1447f6cc7f81598 7f6cf0943da8 1447f6cc7f81988 7f6cf0943da8 1447f6cc7f83308 7f6cf0943da8 1447f6cc7f83ff8 7f6cf0943da8 1447f6cc7f8ceb8 7f6cf0943da8 144Statistics: MT Count TotalSize Class Name7f6cf0943da8 81,26111,701,584 System.Reflection.Emit.DynamicILGeneratorTotal 81,261 objects, 11,701,584 bytes0:000> !gcroot 7f6cc7f7a3f0Found 0 unique roots.0:000> !gcroot 7f6b67d00990Found 0 unique roots.0:000> !gcroot 7f6cc7f83ff8Found 0 unique roots.从卦中看,比较奇怪的是为什么这几个 DynamicILGenerator 样本都没有引用根呢?这里又藏了什么玄机呢?
如果你有大量的dump分析经验,我相信你马上就会想到一个东西,对,它就是 finalizequeue,因为有析构但未被回收自然就想到了它,输出如下:
0:000> !fq -statSyncBlocks to be cleaned up: 0Free-Threaded Interfaces to be released: 0MTA Interfaces to be released: 0STA Interfaces to be released: 0----------------------------------Heap 0generation 0 has 25 objects (7f6b29d58238->7f6b29d58300)generation 1 has 90,693 objects (7f6b29ca7010->7f6b29d58238)generation 2 has 0 objects (7f6b29ca7010->7f6b29ca7010)Ready for finalization 4,088,657 objects (7f6b29d58488->7f6b2bc89f10)------------------------------Statistics for all finalizable objects (including all objects ready for finalization):这一卦真的太灵验了,从尼玛 Ready for finalization 4,088,657 objects 中发现有 408w 的对象在freachable中等待释放,看样子FinalizerThread 有点麻烦了。
不管怎么说,直觉告诉我马上就要真相大白了,有点抑制不住内心的喜悦,接下来切过去观察 FinalizerThread 的调用栈,输出如下:
0:000> ~~[11d83]slibpthread_2_17+0xbde2:00007f6d`6816ede2 4989c6 mov r14,rax0:005> k# Child-SP RetAddr Call Site0000007f6d`644892e000007f6d`67143fd6 libpthread_2_17+0xbde20100007f6d`6448933000007f6d`67143ca1 libcoreclr!CorUnix::CPalSynchronizationManager::ThreadNativeWait+0x126 [/__w/1/s/src/coreclr/pal/src/synchmgr/synchmanager.cpp @ 488] 0200007f6d`6448939000007f6d`67148e39 libcoreclr!CorUnix::CPalSynchronizationManager::BlockThread+0x1d1 [/__w/1/s/src/coreclr/pal/src/synchmgr/synchmanager.cpp @ 307] 03 (Inline Function) --------`-------- libcoreclr!CorUnix::InternalSleepEx+0x61 [/__w/1/s/src/coreclr/pal/src/synchmgr/wait.cpp @ 850] 0400007f6d`644893f0 00007f6d`66db49f7 libcoreclr!SleepEx+0x99 [/__w/1/s/src/coreclr/pal/src/synchmgr/wait.cpp @ 285] 0500007f6d`6448944000007f6d`66e0c53b libcoreclr!Thread::UserSleep+0x147 [/__w/1/s/src/coreclr/vm/threads.cpp @ 4264] 0600007f6d`6448949000007f6c`fbde865a libcoreclr!ThreadNative::Sleep+0xbb [/__w/1/s/src/coreclr/vm/comsynchronizable.cpp @ 471] 0700007f6d`644895f0 00007f6c`fea03c0b System_Private_CoreLib!System.Threading.Thread.Sleep+0x1a [/_/src/libraries/System.Private.CoreLib/src/System/Threading/Thread.cs @ 357] 0800007f6d`6448962000007f6c`fea03ac9 xxxx_7f6cb4034000!0900007f6d`6448966000007f6d`66fbc277 xxxx_7f6cb4034000!0a 00007f6d`6448970000007f6d`66df1dee libcoreclr!CallDescrWorkerInternal+0x7c [/__w/1/s/src/coreclr/pal/inc/unixasmmacrosamd64.inc @ 854] 0b (Inline Function) --------`-------- libcoreclr!CallDescrWorkerWithHandler+0x59 [/__w/1/s/src/coreclr/vm/callhelpers.cpp @ 67] 0c 00007f6d`6448972000007f6d`66d19632 libcoreclr!DispatchCallSimple+0xfe [/__w/1/s/src/coreclr/vm/callhelpers.cpp @ 220] 0d 00007f6d`644897b0 00007f6d`66e02a6a libcoreclr!ExceptionNotifications::DeliverExceptionNotification+0x420e 00007f6d`6448980000007f6d`66e0269a libcoreclr!InvokeUnhandledSwallowing+0xaa [/__w/1/s/src/coreclr/vm/comdelegate.cpp @ 3227] 0f00007f6d`6448988000007f6d`66cbb5c3 libcoreclr!DistributeUnhandledExceptionReliably+0x32a [/__w/1/s/src/coreclr/vm/comdelegate.cpp @ 3291] 1000007f6d`64489aa0 00007f6d`66cbb30f libcoreclr!AppDomain::RaiseUnhandledExceptionEvent+0x93 [/__w/1/s/src/coreclr/vm/appdomain.cpp @ 4328] 1100007f6d`64489b10 00007f6d`66d160ad libcoreclr!AppDomain::OnUnhandledException+0xdf [/__w/1/s/src/coreclr/vm/appdomain.cpp @ 4270] 1200007f6d`64489b90 00007f6d`66d14ebd libcoreclr!NotifyAppDomainsOfUnhandledException+0xdd13 (Inline Function) --------`-------- libcoreclr!InternalUnhandledExceptionFilter_Worker(_EXCEPTION_POINTERS*)::$_3::operator() const+0xfc [/__w/1/s/src/coreclr/vm/excep.cpp @ 4815] 1400007f6d`64489c10 00007f6d`66db7045 libcoreclr!InternalUnhandledExceptionFilter_Worker+0x26d [/__w/1/s/src/coreclr/vm/excep.cpp @ 4896] 15 (Inline Function) --------`-------- libcoreclr!ThreadBaseRedirectingFilter+0xc [/__w/1/s/src/coreclr/vm/threads.cpp @ 7427] 16 (Inline Function) --------`-------- libcoreclr!ManagedThreadBase_DispatchOuter(ManagedThreadCallState*)::$_6::operator()(ManagedThreadBase_DispatchOuter(ManagedThreadCallState*)::TryArgs*) const::{lambda(PAL_SEHException&)#1}::operator() const+0x16 [/__w/1/s/src/coreclr/vm/threads.cpp @ 7525] 17 (Inline Function) --------`-------- libcoreclr!ManagedThreadBase_DispatchOuter(ManagedThreadCallState*)::$_6::operator() const+0x5d2 [/__w/1/s/src/coreclr/vm/threads.cpp @ 7525] 1800007f6d`64489cc0 00007f6d`66db71cd libcoreclr!ManagedThreadBase_DispatchOuter+0x665 [/__w/1/s/src/coreclr/vm/threads.cpp @ 7549] 19 (Inline Function) --------`-------- libcoreclr!ManagedThreadBase_NoADTransition+0x18 [/__w/1/s/src/coreclr/vm/threads.cpp @ 7593] 1a 00007f6d`64489de0 00007f6d`66e3b648 libcoreclr!ManagedThreadBase::FinalizerBase+0x2d [/__w/1/s/src/coreclr/vm/threads.cpp @ 7619] 1b00007f6d`64489e1000007f6d`67150a2e libcoreclr!FinalizerThread::FinalizerThreadStart+0x58 [/__w/1/s/src/coreclr/vm/finalizerthread.cpp @ 391] 1c 00007f6d`64489e3000007f6d`6816aea5 libcoreclr!CorUnix::CPalThread::ThreadEntry+0x24e [/__w/1/s/src/coreclr/pal/src/thread/thread.cpp @ 1865] 1d 00007f6d`64489ee0 00007f6d`6746fb0d libpthread_2_17+0x7ea51e 00007f6d`64489f80 ffffffff`ffffffff libc_2_17+0xfeb0d1f00007f6d`64489f88 00000000`000000000xffffffff`ffffffff尼玛,这一卦打的真离谱,怎么终结器线程在 Sleep 里? 接下来根据 !ip2md 00007f6cfea03ac9 将代码导出来,截图如下:

啥?要暂停1h?这代码真的有点看不懂了,有知道的大牛看看这个逻辑咋样!
这次生产事故的分析难度在我的旅程中还是蛮高的,它需要根据分析过程中的多个琐碎的碎片信息整理推理出完整的证据链,说实话没有多年的dump分析经验,这个问题真的很难搞定!