关于.net:又一起NET程序挂死-用-Windbg-抽丝剥茧式的真实案例分析

31次阅读

共计 4943 个字符,预计需要花费 13 分钟才能阅读完成。

一:背景

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) 尽快失去开释。

更多高质量干货:参见我的 GitHub: dotnetfly

正文完
 0