记一次 .NET 某金融企业 WPF 程序卡死分析

2022 年 8 月 29 日
筆記
windbg

一：背景

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 可以快速结束。

Tags: windbg