記一次 .NET 某金融企業 WPF 程式卡死分析

一：背景

1. 講故事

前段時間遇到了一個難度比較高的 dump，經過幾個小時的探索，終於給找出來了，在這裡做一下整理，希望對大家有所幫助，對自己也是一個總結，好了，老規矩，上 WinDBG 說話。

二：WinDbg 分析

1. 為什麼會卡死

既然程式卡死，那肯定是被凍住了，所以看下主執行緒此時在做什麼。


0:000:x86> !clrstack 
OS Thread Id: 0xe20 (0)
Child SP       IP Call Site
0034d5e8 000bc4b8 [HelperMethodFrame_1OBJ: 0034d5e8] System.Threading.SynchronizationContext.WaitHelper(IntPtr[], Boolean, Int32)
0034d88c 73fd7623 System.Windows.Threading.DispatcherSynchronizationContext.Wait(IntPtr[], Boolean, Int32)
0034d8a0 713eab08 System.Threading.SynchronizationContext.InvokeWaitMethodHelper(System.Threading.SynchronizationContext, IntPtr[], Boolean, Int32)
0034dac0 72231396 [GCFrame: 0034dac0] 
0034dc04 72231396 [HelperMethodFrame_1OBJ: 0034dc04] System.Threading.Thread.JoinInternal(Int32)

從程式碼的 Thread.JoinInternal() 方法看，它正在等待另一個執行緒，接下來用 !dso 找一下這個 Thread 物件，發現標記的是託管執行緒 34，資訊如下：


0:000:x86> !DumpObj /d 02bef5c8
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name

7151f6bc  40018a7       28         System.Int32  1 instance       34 m_ManagedThreadId

接下來切到 34 號執行緒使用 k 命令看下它正在做什麼？


0:038:x86> kb
 # ChildEBP RetAddr      Args to Child              
00 0ee9ede0 77708dd4     0000003c 00000000 00000000 ntdll_776d0000!NtWaitForSingleObject+0x15
01 0ee9ede0 77708cb8     00000000 00000000 096346b0 ntdll_776d0000!RtlpWaitOnCriticalSection+0x13e
02 0ee9ee08 5da08101     0963c554 0963c4ec 0ee9ee34 ntdll_776d0000!RtlEnterCriticalSection+0x150
03 0ee9ee18 5db16581     0963c554 096346b0 20000000 quartz!CBlockLock<CKsOpmLib>::CBlockLock<CKsOpmLib>+0x14

從輸出的 RtlEnterCriticalSection 方法看，它正在等待臨界區資源，接下來使用 !cs 看下這個臨界區資源到底被誰持有？


0:038:x86> !cs 0963c554
-----------------------------------------
Critical section   = 0x0963c554 (+0x963C554)
DebugInfo          = 0x0e4859e0
LOCKED
LockCount          = 0x1
WaiterWoken        = No
OwningThread       = 0x00000ee4
RecursionCount     = 0x1
LockSemaphore      = 0x3C
SpinCount          = 0x00000000

可以看到，持有這個臨界區的執行緒是 0x00000ee4 ,接下來我們切過去看下這個執行緒此時正在做什麼？


0:038:x86> ~~[0x00000ee4]s
ntdll_776d0000!ZwWaitForMultipleObjects+0x15:
776f014d 83c404          add     esp,4

0:041:x86> !clrstack 
Child SP       IP Call Site
0f4ff784 0000002b [GCFrame: 0f4ff784] 
0f4ff85c 0000002b [GCFrame: 0f4ff85c] 
0f4ff878 0000002b [HelperMethodFrame_1OBJ: 0f4ff878] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0f4ff8f4 713ea287 System.Threading.Monitor.Enter(System.Object, Boolean ByRef)
...

0:041:x86> !dso
OS Thread Id: 0xee4 (41)
ESP/REG  Object   Name
0F4FF7B8 028d9de8 System.Drawing.Bitmap

從輸出資訊中可以看到, 執行緒 0x00000ee4 正在 lock 鎖上等待， lock 的物件是 Bitmap，接下來的問題是誰正在持有 lock 鎖呢？可以使用 !syncblk 觀察同步塊表即可。


0:041:x86> !syncblk
CLR Version: 4.6.1055.0
SOS Version: 4.8.4300.0
Index         SyncBlock MonitorHeld Recursion Owning Thread Info          SyncBlock Owner
SyncBlock 856 is invalid, continuing...
-----------------------------
Total           1046
CCW             59
RCW             24
ComClassFactory 5
Free            832

從輸出中可以看到，此時的 syncblk 已經損壞，也就無法知道當前是哪個執行緒 lock 了 Bitmap，到這裡難度就驟然增大了。。。

問題還得要解決，那怎麼辦呢？只能試著自己把 syncblk 給恢復出來，入口就是 Bitmap 上的同步塊索引。

2. 根據索引恢復同步塊表

瞭解 lock 的朋友應該知道，它在 CLR 層面是 AwareLock ，而這個鎖就承載了絕大多數的 syncblk 資訊。


0:007> dt coreclr!AwareLock
   +0x000 m_lockState      : AwareLock::LockState
   +0x004 m_Recursion      : Uint4B
   +0x008 m_HoldingThread  : Ptr64 Thread
   +0x010 m_TransientPrecious : Int4B
   +0x014 m_dwSyncIndex    : Uint4B
   +0x018 m_SemEvent       : CLREvent
   +0x028 m_waiterStarvationStartTimeMs : Uint4B

其中：

m_HoldingThread：當前 lock 的持有執行緒。
m_dwSyncIndex: 當前的同步塊索引。
m_SemEvent: lock 底層的號誌

上面這三個值，其實我是知道兩個的，一個可以從 Bitmap 頭上獲取 m_dwSyncIndex ，一個可以從 kb 命令的 WaitForMultipleObjectsEx 引數中提取 m_SemEvent ,輸出如下：


0:041:x86> dp 028d9de8 -0x4 L1
028d9de4  08000358

0:041:x86> kb
 # ChildEBP RetAddr      Args to Child              
00 0f4ff568 77250962     00000001 0f4ff51c 00000001 ntdll_776d0000!ZwWaitForMultipleObjects+0x15
01 0f4ff568 75a41a2c     0f4ff51c 0f4ff590 00000000 KERNELBASE!WaitForMultipleObjectsEx+0x100

0:041:x86> dp 0f4ff51c L1
0f4ff51c  00000ff8

可以看到 Bitmap 的索引號為 0x358，接下來可以全記憶體搜尋，全稱為： 80000358 ，記得這裡是 80000358 而不是 08000358 。


0:000:x86> s-d 0 L?0xffffffff 0x80000358
051ed11c  80000358 00000002 80000370 00000003  X.......p.......
051f3fcc  80000358 0000008e 80000370 00000090  X.......p.......
05229980  80000358 80000038 00000005 80000050  X...8.......P...
052b5c00  80000358 80000028 00000006 80000040  X...(.......@...
0531c28c  80000358 00000010 800004f0 00000000  X...............
0535ed54  80000358 0000014d 80000370 000004c5  X...M...p.......
05432f0c  80000358 0000a424 80000370 00000000  X...$...p.......
109e0284  80000358 00000680 80000370 00000730  X.......p...0...
192e6690  80000358 ffffffff 00000000 192e8848  X...........H...
192ee1b4  80000358 00000ff8 0000000d 00000000  X...............
558d209c  80000358 00000067 80000370 00000071  X...g...p...q...
5d791104  80000358 00000012 80000370 00000013  X.......p.......
6d331104  80000358 0000038a 80000370 0000038b  X.......p.......
758a004c  80000358 00000010 800003d0 00000018  X...............

搜出來有很多，但不要慌，根據 AwareLock 的偏移，已知的兩個值 80000358 00000ff8 會是有序排列的，所以正確的地址應該是 192ee1b4，現在我們可以向前偏移 0x10 個位置就能找到 AwareLock 的首地址。


0:000:x86> dp 192ee1b4-0x10 L8
192ee1a4  00000003 00000029 192ebf00 00000001
192ee1b4  80000358 00000ff8 0000000d 00000000

0:007> dt coreclr!AwareLock
   +0x000 m_lockState      : AwareLock::LockState
   +0x004 m_Recursion      : Uint4B
   +0x008 m_HoldingThread  : Ptr64 Thread
   +0x010 m_TransientPrecious : Int4B
   +0x014 m_dwSyncIndex    : Uint4B
   +0x018 m_SemEvent       : CLREvent
   +0x028 m_waiterStarvationStartTimeMs : Uint4B

再對應剛才的結構，可以看到 192ebf00 其實就是我們要找的 m_HoldingThread 執行緒，但這個執行緒只是 CLR Thread 類，接下來再找下它關聯的是哪一個託管執行緒ID。


0:000:x86> dp 192ebf00 L8
192ebf00  722c0002 01039820 00000000 ffffffff
192ebf10  00000000 00000000 00000000 0000000c
0:000:x86> ? 0000000c
Evaluate expression: 12 = 0000000c

終於我們找到了，原來是託管執行緒ID=12，接下來用 !t 顯示出所有執行緒，觀察下到底怎麼回事。


0:000:x86> !t
       ID OSID ThreadOBJ    State GC Mode     GC Alloc Context  Domain   Count Apt Exception
   0    1  e20 006f0690   2026020 Preemptive  02CCEC04:00000000 006e94f0 0     STA 
   2    2  e2c 006fe5d8     2b220 Preemptive  02CB6AB0:00000000 006e94f0 0     MTA (Finalizer) 
   5    5  e68 0971d0f8     2b220 Preemptive  02D091BC:00000000 006e94f0 0     MTA 
   7    6  e7c 0e379d50   3029220 Preemptive  00000000:00000000 006e94f0 0     MTA (Threadpool Worker) 
XXXX    7    0 0e384a70   1039820 Preemptive  00000000:00000000 006e94f0 0     Ukn (Threadpool Worker) 
   8    9  e8c 0e376d18   102a220 Preemptive  00000000:00000000 006e94f0 0     MTA (Threadpool Worker) 
  11   11  ea8 0e3b8250   1020220 Preemptive  00000000:00000000 006e94f0 0     Ukn (Threadpool Worker) 
  12   15  f4c 0e487a90   202b220 Preemptive  00000000:00000000 006e94f0 0     MTA 
  13   16  f54 0e488f78   202b220 Preemptive  00000000:00000000 006e94f0 0     MTA

上面的 ID 列就是 託管執行緒的標號，但很可惜，這個執行緒已經消失了，而且搜尋託管堆上的所有 Thread，都沒有這個ID號，說明這個執行緒已經被 GC 回收掉了。

3. 真相大白

由於程式碼比較隱私，這裡就繪製個模型吧，截圖如下：

這裡有兩點資訊：

TestEvent 會被 C++ 觸發。
lock 中會執行 C++ 邏輯。

當 tid=12 進入了 lock 鎖時，由於某種原因， 1 或者 2 處的 C++ 程式碼執行了類似 Thread.Abort 的邏輯，這就導致託管ID 和 OS 執行緒ID 斷了聯絡，後續就被 GC 給回收了，底層邏輯大概就是這樣。

三：總結

是不是有點顛覆三觀，你認為 lock 能 100% 的實現原子化，其實也不一定，而且還讓程式遭受著嚴重的後果。

在《.NET 高階偵錯》這本書中也有類似的講述，感興趣的朋友可以看一下。

最後的修復方法就是：不要在 TestEvent 中處理 C++ 邏輯，因為這塊處理比較慢，將其提到單獨執行緒中處理，也讓 TestEvent 可以快速結束。