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

[[394026]]

本文转载自微信公众号「一线码农聊技术」，作者一线码农聊技术。转载本文请联系一线码农聊技术公众号。

一：背景

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 Owner 
   76   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:   no 
                                                                         Lock   
       ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception 
   0    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: 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) 尽快得到释放。