记一次 .NET 某金融企业 WPF 程序卡死分析
Posted dotNET跨平台
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了记一次 .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 可以快速结束。
以上是关于记一次 .NET 某金融企业 WPF 程序卡死分析的主要内容，如果未能解决你的问题，请参考以下文章