又一起.NET程式掛死, 用 Windbg 抽絲剝繭式的真實案例分析

一線碼農發表於2021-04-19

一:背景

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

圖片名稱

相關文章