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

一：背景

1. 讲故事

前天有位粉丝朋友在后台留言让我帮忙看看他的 Winform程序 UI无响应 + 410线程 到底是啥情况，如下图：

说实话，能看到这些真实案例我是特别喜欢的???????????? ，就像医生看病，光停留在理论和那些 demo 上，那是没有前途的，如果有朋友在这块搞不定的话，我可以免费帮你解读 dump，再附送一篇博客详述。

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

WinForm 出现高负载的情况，我至今还是没遇到????????????，如果说卡在某个锁上，基本都属于这类，有了这个先入为主的思路，接下来就可以祭出 windbg 一探究竟了。

二：windbg 分析

1. 查找 CLR 同步块表

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


0:000> !syncblk
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner76   070e5fa4           67         1 17367570 15e8 218   03e6dd68 System.IO.Ports.SerialStream
-----------------------------
Total           789
CCW             39
RCW             2
ComClassFactory 1
Free            535

我去，从卦象上来看情况很不好，我来简单分析下。

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
Hosted Runtime:   noLock  ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception0    1  c64 00cc3de0     24220 Preemptive  042E1884:00000000 00cbc0a0 0     STA 214  240 1398 16702b90   1029220 Preemptive  00000000:00000000 00cbc0a0 0     MTA (Threadpool Worker) 215  323  b5c 12ab7260   1029220 Preemptive  00000000:00000000 00cbc0a0 0     MTA (Threadpool Worker) 216  290 1858 16c21c98   1029220 Preemptive  00000000:00000000 00cbc0a0 0     MTA (Threadpool Worker) 218  117 15e8 17367570   1029220 Preemptive  00000000:00000000 00cbc0a0 1     MTA (Threadpool Worker) ...

对，就是 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: 08644dc00: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

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

1. CPU爆高

2. 内存暴涨

3. 资源泄漏

4. 崩溃死锁

5. 程序呆滞

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