资讯详情

又一起.NET程序挂死, 用 Windbg 抽丝剥茧式的真实案例分析

一:背景

1. 讲故事

前天有粉丝朋友在后台留言,让我帮忙看看他。 Winform程序UI无响应 410线程情况如下图所示:

说实话,我特别喜欢看到这些真实的案例。 ,就像医生看病一样,只停留在理论和那些 demo 上面,没有未来。如果有朋友在这里做不到,我可以免费帮你解读 dump,再附一个博客细节。

好了,言归正传,既然粉丝朋友已经提到了高达410线程,我的本能反应是要么是高负载,要么是野线程,后者大多是无数的新线程卡在上。

WinForm 高负前为止,我还没有遇到高负荷的情况。如果卡在锁上,基本上属于这类。有了这个先入为主的想法,我们可以牺牲它 windbg 一探究竟。

二:windbg 分析

1. 查找 CLR 同步块表

十个人用锁,八个人用 lock, 所以先用!syncblk看程序的锁。

0:000>!syncblk IndexSyncBlockMonitorHeldRecursionOwningThreadInfoSyncBlockOwner 76070e5fa46711736757015e821803e6dd68System.IO.Ports.SerialStream ----------------------------- Total789 CCW39 RCW2 ComClassFactory1 Free535  

我去,从卦象的角度来看,情况很糟糕,我来简单分析一下。

  • MonitorHeld = 67

这个 67 表示当前有 1 线程持有锁,是的 33 一个线程在等锁,一定有朋友想问怎么算。很简单:当一个线程持有锁时MonitorHeld 1,当线程等待锁时MonitorHeld 2,所以表达式是: 67= [1 66=(33*2)]

  • Owning Thread Info = 17367570 15e8 218

以上三个信息都表示当前持有线程,您可以查看最终信息 218,它是 windbg 映射线程ID,如果不以用 !t 一探究竟。

0:000>!t ThreadCount:315 UnstartedThread:0 BackgroundThread:302 PendingThread:0 DeadThread:0 HostedRuntime:no Lock IDOSIDThreadOBJStateGCModeGCAllocContextDomainCountAptException 01c6400cc3de024220Preemptive042E1884:0000000000cbc0a00STA 214240139816702b901029220Preemptive00000000:0000000000cbc0a00MTA(ThreadpoolWorker) 215323b5c12ab72601029220Preemptive00000000:0000000000cbc0a00MTA(ThreadpoolWorker) 216290185816c21c981029220Preemptive00000000:0000000000cbc0a00MTA(ThreadpoolWorker) 21811715e8173675701029220Preemptive00000000:0000000000cbc0a01MTA(ThreadpoolWorker) ...  

对,就是 218 罪魁祸首持有锁,导致 33 无辜地等待线程。

  • SyncBlock Owner = System.IO.Ports.SerialStream

也许你会好奇,到底 lock 持有哪个对象?SyncBlock Owner上看就是SerialStream, ??,原来哥哥在玩串口编码,我先膜拜一下。

2. 查看线程栈

知道是 218 惹的祸,接下来可以看看它的线程栈,到底在干什么?

有些朋友可能看不懂上面的调用栈。我画了一张简图:

从图中看,来自 ThreadPool 的线程在用户自定义DataReceived方法卡住了,为了方便我用!DumpIL看看这个方法 IL 代码。

0:218>!name2ee*!xxx.TYAComYB.DataReceived Module:03b10cc4 Assembly:YKit.dll Token:      06000108
MethodDesc:  08533584
Name:        xxx.TYAComYB.DataReceived(System.Object, System.IO.Ports.SerialDataReceivedEventArgs)
JITTED Code Address: 08644dc0

0:218> !dumpil 08533584
ilAddr = 05dc2dd8
IL_0000: nop 
IL_0001: nop 
IL_0002: nop 
IL_0003: ret 

🐂👃,这代码居然藏了钩子,用 !dumpil 居然看不到代码,难怪在线程栈上看到了类似混淆的方法:xxx.TYAComYB.EYLlXL2bKH(),不过看反汇编是没有问题的,简化如下:

0:218> !U /d 08644edf
08644ddd e86edaffff      call    08642850 (xxxx.com.ComPort.get_isOpen(), mdToken: 060004b6)
08644df4 e807deffff      call    08642c00 (xxxx.YBComParam.get_DataPacketLen(), mdToken: 0600010c)
08644dfb b92a3e136e      mov     ecx,offset mscorlib_ni!System.GC.ReRegisterForFinalize(System.Object) <PERF> (mscorlib_ni+0x3e2a) (6e133e2a)
08644e00 e80fd460f8      call    00c52214 (JitHelp: CORINFO_HELP_NEWARR_1_VC)
08644e15 e8e6ddffff      call    08642c00 (xxx.YBComParam.get_DataPacketLen(), mdToken: 0600010c)
08644e22 e8edac4d68      call    System_ni+0x13fb14 (70b1fb14) (System.IO.Ports.SerialPort.Read(Byte[], Int32, Int32), mdToken: 06004173)
08644e2e ff153836b103    call    dword ptr ds:[3B13638h] (xxxx.LogKit.WriteLine(System.Exception), mdToken: 06000183)
08644e59 e8a2ddffff      call    08642c00 (xxxx.YBComParam.get_DataPacketLen(), mdToken: 0600010c)
08644e64 ff1580355308    call    dword ptr ds:[8533580h] (xxxx.TYAComYB.EYLlXL2bKH(), mdToken: 06000107)
08644e9b ff15a4265308    call    dword ptr ds:[85326A4h] (xxxx.YBComParam.get_DataPacketStart(), mdToken: 0600010e)
08644ea8 e837e34e66      call    mscorlib_ni!System.Convert.ToByte(System.String, Int32) (6eb331e4)
08644ed9 ff1580355308    call    dword ptr ds:[8533580h] (xxxx.TYAComYB.EYLlXL2bKH(), mdToken: 06000107)

反正做的事情挺多,我就懒得分析了。

接下来看看那 33 个线程怎么就卡在 SerialStream 上呢?可以用 ~*e !clrstack 扫一下所有的 threads,抽几个看看。

0:218> ~*e !clrstack
OS Thread Id: 0xc64 (0)
Child SP       IP Call Site
OS Thread Id: 0x13d8 (330)
Child SP       IP Call Site
1b1aec90 77c8016d [GCFrame: 1b1aec90] 
1b1aee30 77c8016d [GCFrame: 1b1aee30] 
1b1aede0 77c8016d [HelperMethodFrame: 1b1aede0] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
1b1aee70 710d6b54 System.IO.Ports.SerialPort.CatchReceivedEvents(System.Object, System.IO.Ports.SerialDataReceivedEventArgs)
1b1aeeac 710d9520 System.IO.Ports.SerialStream+EventLoopRunner.CallReceiveEvents(System.Object)
1b1aeec0 6e45e356 System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(System.Object)
1b1aeec8 6e43da07 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
1b1aef34 6e43d956 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
1b1aef48 6e45f120 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
1b1aef5c 6e45e929 System.Threading.ThreadPoolWorkQueue.Dispatch()
1b1aefac 6e45e7d5 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
1b1af1d4 71382552 [DebuggerU2MCatchHandlerFrame: 1b1af1d4] 

我去,居然都卡在 System.IO.Ports.SerialPort.CatchReceivedEvents 这里了,而且还是 framework 提供的,这就很困惑了。

3. 分析 SerialPort 源码

要想看 SerialPort 类的源码,可以用 ILSpy,如下图所示:

看到这里,再结合我刚才画的图,思路是不是就清晰多了,究其原因就是 dataReceived(this, e); 触发的用户回调函数迟迟得不到结束,导致底层大量的线程在 lock 处等待。

三:总结

为了理解为啥底层会创建那么多线程,我特意还查了下串口类 SerialPort,说串口发送方送过来的数据,接收方可以主动接收,可以被动接收,被动就是这种 事件模式,接收方收到发送方送来的数据时,操作系统会让 CLR 通过 Thread 来处理这段回调事件,所以从卦象上看就是典型的接收方处理能力不足造成的大量 lock 等待。

大概提两点优化措施:

  • 提升 xxx.TYAComYB.DataReceived 方法中业务逻辑的处理能力。

  • 增加蓄水池,让底层的 lock (serialStream) 尽快得到释放。

END

工作中的你,是否已遇到 ... 

等紧急事件,全公司都指望着你能解决...  危难时刻才能展现你的技术价值,作为专注于.NET高级调试的技术博主,欢迎微信搜索:,免费协助你分析Dump文件,希望我能将你的踩坑经验分享给更多的人。

标签: dd70f120三社二极管模块

锐单商城拥有海量元器件数据手册IC替代型号,打造 电子元器件IC百科大全!

锐单商城 - 一站式电子元器件采购平台