记一次 .NET 某医院门诊软件 卡死分析
Posted
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了记一次 .NET 某医院门诊软件 卡死分析相关的知识，希望对你有一定的参考价值。
一：背景
1. 讲故事
前几天有位朋友找到我，说他们的软件在客户那边卡死了，让我帮忙看下是怎么回事？我就让朋友在程序卡死的时候通过 任务管理器 抓一个 dump 下来，虽然默认抓的是 wow64 ，不过用 soswow64.dll 转还是可以的，参考命令如下：
.load C:\\soft\\soswow64\\soswow64.dll
!wow64exts.sw
接下来就可以分析了哈。
二：WinDbg 分析
1. 为什么会卡死
首先用 !t 简单看一下主线程的 COM Apartment 模式，如果是 STA 那就是窗体程序，比如 WPF，WinForm 之类的，输出如下：
0:000:x86> !t
ThreadCount: 39
UnstartedThread: 0
BackgroundThread: 12
PendingThread: 0
DeadThread: 26
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
0 1 1928 01aee0b0 2026020 Preemptive 041D496C:00000000 01ae88a8 2 STA
...
既然是窗体程序那就看主线程吧，使用 ~0s;!clrstack 命令。
0:000:x86> !clrstack
OS Thread Id: 0x1928 (0)
Child SP IP Call Site
0177dff8 0167e1f8 [HelperMethodFrame_1OBJ: 0177dff8] System.Threading.SynchronizationContext.WaitHelper(IntPtr[], Boolean, Int32)
0177e29c 6a6fc693 System.Windows.Threading.DispatcherSynchronizationContext.Wait(IntPtr[], Boolean, Int32)
0177e2b0 71e36d54 System.Threading.SynchronizationContext.InvokeWaitMethodHelper(System.Threading.SynchronizationContext, IntPtr[], Boolean, Int32) [f:\\dd\\ndp\\clr\\src\\BCL\\system\\threading\\synchronizationcontext.cs @ 349]
0177e4d8 73220076 [GCFrame: 0177e4d8]
0177e5f8 73220076 [GCFrame: 0177e5f8]
0177e6d8 73220076 [GCFrame: 0177e6d8]
0177e6f4 73220076 [HelperMethodFrame_1OBJ: 0177e6f4] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0177e770 18078b93 System.Speech.Internal.Synthesis.AudioDeviceOut.Abort()
0177e79c 17270698 System.Speech.Internal.Synthesis.VoiceSynthesis.Abort()
0177e7e8 065ec76b System.Speech.Synthesis.SpeechSynthesizer.SpeakAsyncCancelAll()
0177e7f0 065ec728 xxx.xxx.Speek(System.String)
...
从卦中看是一个 语音模块，还有 Speek 功能，挺有意思。。。 还 Speek 啥呢？可以用 !mdso 看一下。
0:000:x86> !mdso
Thread 0:
Location Object Type
------------------------------------------------------------
0177e060 04176eb8 System.IntPtr[]
...
0177e7f8 03be9504 System.String "请先登录验证身份"
哈哈，上面只是花絮，继续看线程栈会发现代码卡在 Monitor.ReliableEnter 上，也就是等待 lock 锁，接下来用 kb 把 锁对象提取出来，即 clr!JITutil_MonReliableEnter 方法的第一个参数 03be11b4，输出如下：
0:000:x86> kb
...
17 0177e768 18078b93 03be11b4 00000000 00000000 clr!JITutil_MonReliableEnter+0xb5
18 0177e794 17270698 0177e7bc 73252799 00000000 0x18078b93
19 0177e7e0 065ec76b 0177e808 065ec728 00000000 0x17270698
1a 0177e7e8 065ec728 00000000 03a0b318 03be9504 0x65ec76b
1b 0177e808 1727e09f 00000000 03be0920 04158b98 0x65ec728
1c 0177e824 69181324 04175c04 041199c0 00000001 0x1727e09f
...
0:000:x86> !do 03be11b4
Name: System.Object
MethodTable: 71f200f4
EEClass: 71a715b0
Size: 12(0xc) bytes
File: C:\\Windows\\Microsoft.Net\\assembly\\GAC_32\\mscorlib\\v4.0_4.0.0.0__b77a5c561934e089\\mscorlib.dll
Object
Fields:
None
有了这个对象就可以用 !syncblk 命令观察同步块表，到底是哪个线程在持有不释放？
0:000:x86> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
96 11ac3ee0 3 1 11af0f28 35d4 13 03be11b4 System.Object
-----------------------------
Total 931
CCW 39
RCW 19
ComClassFactory 2
Free 802
0:000:x86> ~13s;!clrstack
ntdll_76fc0000!NtWaitForSingleObject+0xc:
7703159c c20c00 ret 0Ch
OS Thread Id: 0x35d4 (13)
Child SP IP Call Site
17f8f23c 0000002b [InlinedCallFrame: 17f8f23c]
17f8f238 1adf3269 DomainBoundILStubClass.IL_STUB_PInvoke(IntPtr)
17f8f23c 1adf2e82 [InlinedCallFrame: 17f8f23c] System.Speech.Internal.Synthesis.SafeNativeMethods.waveOutClose(IntPtr)
17f8f26c 1adf2e82 System.Speech.Internal.Synthesis.AudioDeviceOut.End()
17f8f298 187a5cd6 System.Speech.Internal.Synthesis.VoiceSynthesis.SpeakText(System.Speech.Internal.Synthesis.SpeakInfo, System.Speech.Synthesis.Prompt, System.Collections.Generic.List`1<System.Speech.Internal.Synthesis.LexiconEntry>)
17f8f304 17271669 System.Speech.Internal.Synthesis.VoiceSynthesis.ThreadProc()
17f8f3b8 71e3710d System.Threading.ThreadHelper.ThreadStart_Context(System.Object) [f:\\dd\\ndp\\clr\\src\\BCL\\system\\threading\\thread.cs @ 74]
17f8f3c4 71e640c5 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\\dd\\ndp\\clr\\src\\BCL\\system\\threading\\executioncontext.cs @ 954]
17f8f430 71e63fd6 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) [f:\\dd\\ndp\\clr\\src\\BCL\\system\\threading\\executioncontext.cs @ 902]
17f8f444 71e63f91 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [f:\\dd\\ndp\\clr\\src\\BCL\\system\\threading\\executioncontext.cs @ 891]
17f8f45c 71e37068 System.Threading.ThreadHelper.ThreadStart() [f:\\dd\\ndp\\clr\\src\\BCL\\system\\threading\\thread.cs @ 111]
17f8f5a0 73220076 [GCFrame: 17f8f5a0]
17f8f784 73220076 [DebuggerU2MCatchHandlerFrame: 17f8f784]
0:013:x86> !t
...
13 14 35d4 11af0f28 2b220 Preemptive 00000000:00000000 01ae88a8 2 MTA
...
从卦中信息看：13号线程持有了 lock 锁，并且它非线程池线程，而是通过 new Thread 出来的，从线程栈看都是sdk函数，综合这些信息，应该是 VoiceSynthesis 创建出来的后台线程，下面的图也可以佐证。
接下来继续看，从线程栈顶上可以观察到最后卡在了 System.Speech.Internal.Synthesis.SafeNativeMethods.waveOutClose 方法处，逆向之后的代码如下：
// System.Speech.Internal.Synthesis.AudioDeviceOut
internal override void End()
if (!_deviceOpen)
throw new InvalidOperationException();
lock (_noWriteOutLock)
_deviceOpen = false;
CheckForAbort();
if (_queueIn.Count != 0)
SafeNativeMethods.waveOutReset(_hwo);
MMSYSERR mMSYSERR = SafeNativeMethods.waveOutClose(_hwo);
由于这是 Windows 的 VoiceSynthesis 模块封装底层函数，经过千锤百炼，理论上出问题的概率会非常小，除非上层有不合理的调用，这种概率会大一些。
2. 是上层不合理的调用吗
这一块我也没玩过，网上搜一下 waveOutReset , waveOutClose ，看下有没有同病相怜的人，结果网上一搜一堆，比如下面这样：
不管怎么说，这一块如果处理不好容易出现死锁和卡死的情况，那是不是正如图中所说 waveOutReset 和 waveOutClose 没有匹配造成的呢？
这就取决于代码中的 _queueIn 集合，可以观察这两个函数的汇编代码提取出这个变量。
0:013:x86> !U /d 1adf2e82
Normal JIT generated code
System.Speech.Internal.Synthesis.AudioDeviceOut.End()
...
1adf2e30 8bf1 mov esi,ecx
...
1adf2e69 8b4608 mov eax,dword ptr [esi+8]
1adf2e6c 83780c00 cmp dword ptr [eax+0Ch],0
1adf2e70 7408 je 1adf2e7a
...
0:013:x86> !U /d 187a5cd6
Normal JIT generated code
System.Speech.Internal.Synthesis.VoiceSynthesis.SpeakText(System.Speech.Internal.Synthesis.SpeakInfo, System.Speech.Synthesis.Prompt, System.Collections.Generic.List`1<System.Speech.Internal.Synthesis.LexiconEntry>)
...
187a5cc8 8b45d0 mov eax,dword ptr [ebp-30h]
187a5ccb 8b486c mov ecx,dword ptr [eax+6Ch]
187a5cd3 ff5014 call dword ptr [eax+14h]
>>> 187a5cd6 58 pop eax
...
0:013:x86> kb 10
# ChildEBP RetAddr Args to Child
...
08 17f8f264 1adf2e82 03be11b4 00000001 00000000 0x1adf3269
09 17f8f290 187a5cd6 187a5e16 03be0d24 043f3520 0x1adf2e82
0a 17f8f2f4 17271669 040efa14 040ef9a4 732515d8 0x187a5cd6
0b 17f8f3b0 71e3710d 03ff3e98 17f8f420 71e640c5 0x17271669
...
仔细观察上面的汇编代码：eax 来自于 esi，esi 来自于 ecx，ecx 最终来自于父函数中的 ebp-30h 的位置，串联起来的命令就是 !do poi(poi(poi(17f8f2f4-30)+6c)+0x8) ，接下来我们 do 一下。
0:000:x86> !do poi(poi(poi(17f8f2f4-30)+6c)+0x8)
Name: System.Collections.Generic.List`1[[System.Speech.Internal.Synthesis.AudioDeviceOut+InItem, System.Speech]]
MethodTable: 16cf20ec
EEClass: 71af6f8c
Size: 24(0x18) bytes
File: C:\\Windows\\Microsoft.Net\\assembly\\GAC_32\\mscorlib\\v4.0_4.0.0.0__b77a5c561934e089\\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
71f2f320 4001891 4 System.__Canon[] 0 instance 03c74538 _items
71f21bb4 4001892 c System.Int32 1 instance 0 _size
71f21bb4 4001893 10 System.Int32 1 instance 1900 _version
71f200f4 4001894 8 System.Object 0 instance 00000000 _syncRoot
71f2f320 4001895 4 System.__Canon[] 0 static <no information>
可以看到此时的 _size=0 ，有可能就是因为上层不合理调用导致这里的 _queueIn 意外为 0 ，最终引发的卡死现象。
3. 真相大白
一时之间也找不到上层哪里有不合理的调用，接下来的思路还是自己研读主线程和13号线程的调用栈，最后发现一个可疑的现象，截图如下：
通过仔细研读底层代码，Speek 会将消息丢到底层的queue队列中，后台线程会提取处理，这里的 SpeakAsyncCancelAll 是完全没必要的。
有了这个消息，就让朋友把这个函数去掉观察下试试，据朋友反馈说没有问题了。
三：总结
这个案例中去掉了意外的 speech.SpeakAsyncCancelAll(); 语句就搞定了，内部深层逻辑也没有再探究了，大概率就是意外的 _queueIn 为 0，让 waveOutReset 和 waveOutClose 方法没有匹配出现，造成了卡死现象。
记一次 .NET 某三甲医院HIS系统 内存暴涨分析
一：背景
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();
}
}
END
工作中的你，是否已遇到 ...
1. CPU爆高
2. 内存暴涨
3. 资源泄漏
4. 崩溃死锁
5. 程序呆滞
等紧急事件，全公司都指望着你能解决... 危难时刻才能展现你的技术价值，作为专注于.NET高级调试的技术博主，欢迎微信搜索: 一线码农聊技术，免费协助你分析Dump文件，希望我能将你的踩坑经验分享给更多的人。
以上是关于记一次 .NET 某医院门诊软件 卡死分析的主要内容，如果未能解决你的问题，请参考以下文章