记一次 .NET某机械臂上位系统卡死分析

net · 浏览次数 : 17

小编点评

一、背景最近有位朋友找到我，他们的程序会偶发性地卡死一段时间，然后又恢复正常。朋友希望我能帮忙找出原因。二、WinDbg分析 1. 主线程在做什么通过k命令观察非托管栈，发现主线程在调用System.Drawing.StringFormat..ctor方法。 2. 无效的句柄会导致卡死吗？根据MSDN，无效的句柄会导致程序崩溃。但在这个场景下，由于win32api没有使用try-catch和SEH集成，返回错误码的方式性能最高，因此不太可能导致程序卡死。 3. 队列是否有积压？通过观察主线程的线程栈，发现BackgroundWorker.Queue当前有227个任务在队列积压。这说明主线程没有问题，只是在忙碌地处理任务。 4. 为什么会卡一阵子？经过分析，发现主线程在调用System.Windows.Forms.Control.InvokeMarshaledCallback方法从队列中取数据。由于该方法非常轴，不懂得变通，导致线程在处理大量任务时变得非常忙碌，从而引发卡死现象。三、总结这次朋友的生产事故给我们分析人员带来了很大的教训。有时候，主线程的一些抛错或阻塞假象会误导我们进入分析误区。因此，调试人员需要具备一双慧眼，及时发现问题并解决问题。

正文

一：背景

1. 讲故事

前些天有位朋友找到我，说他们的程序会偶发性的卡死一段时间，然后又好了，让我帮忙看下怎么回事？窗体类的程序解决起来相对来说比较简单，让朋友用procdump自动抓一个卡死时的dump，拿到dump之后，上 windbg 说话。

二：WinDbg 分析

1. 主线程在做什么

要想看主线程在做什么，很显然用 k 命令观察非托管栈即可。


0:000> k
 # Child-SP          RetAddr               Call Site
00 000000ef`11d1cb70 00007ffc`e65ddc4a     ntdll!RtlSetLastWin32Error+0x38
01 000000ef`11d1cbc0 00007ffc`e660e1a4     clr!JIT_RareDisableHelperWorker+0xca
02 000000ef`11d1cd00 00007ffc`b5c4ea25     clr!JIT_RareDisableHelper+0x14
03 000000ef`11d1cd40 00007ffc`b5c41d35     System_Drawing_ni+0x6ea25
04 000000ef`11d1ce00 00007ffc`87948876     System_Drawing_ni!System.Drawing.StringFormat..ctor+0x15
....
10 000000ef`11d1d8b0 00007ffc`881fc86f     xxx!xxx.AutoResizeColumns+0x106
...

从卦中数据看，托管的栈顶上有一个 RtlSetLastWin32Error 函数，看样子 JIT_RareDisableHelperWorker 方法中某一个函数返回错误码了，那这个错误码是多少呢？要知道这个答案，先要知道它的签名是什么样的，参考链接： https://source.winehq.org/WineAPI/RtlSetLastWin32Error.html


void RtlSetLastWin32Error
(
    DWORD err
)

从签名可以看到，这个 err 是一个 int ，接下来观察 RtlSetLastWin32Error 方法的 rcx 寄存器，有没有存到线程栈上，如果有的话直接提取即可。


0:000> uf ntdll!RtlSetLastWin32Error
ntdll!RtlSetLastWin32Error:
00007ffd`01a00780 894c2408        mov     dword ptr [rsp+8],ecx
00007ffd`01a00784 4883ec48        sub     rsp,48h
00007ffd`01a00788 488b05813d1300  mov     rax,qword ptr [ntdll!_security_cookie (00007ffd`01b34510)]
00007ffd`01a0078f 4833c4          xor     rax,rsp
....

0:000> k
 # Child-SP          RetAddr               Call Site
00 000000ef`11d1cb70 00007ffc`e65ddc4a     ntdll!RtlSetLastWin32Error+0x38
01 000000ef`11d1cbc0 00007ffc`e660e1a4     clr!JIT_RareDisableHelperWorker+0xca

0:000> dd 000000ef`11d1cbc0 L1
000000ef`11d1cbc0  00000006

从卦中看这个 err=6 ，那这个错误码是什么意思呢？继续查 MSDN： https://learn.microsoft.com/zh-cn/windows/win32/debug/system-error-codes--0-499-

从卦中可以清晰的看到，原来是 无效的句柄 导致的，那这个错误会导致程序的卡死吗？

2. 无效的句柄会卡程序吗

按照我的过往经验没有这么一说，其实 win32api 不像编程语言直接用 try catch 与 SEH 集成，返回错误码的这种方式编码起来虽然麻烦，但性能是最高的，所以这玩意导致程序卡死基本上是不可能的，那接下来的分析方向在哪里呢？其实在这种场景下抓多dump就尤为重要了，毕竟多个dump之间可以相互参考来观察程序的走势，目前是没有这个条件的，那就从其他的路子上探究吧。

接下来我们试探性的观察所有的托管线程栈，看看他们此时都在做什么。


0:000> ~*e !clrstack
OS Thread Id: 0x555c (98)
        Child SP               IP Call Site
000000ef180fd0b8 00007ffd01a4dc04 [HelperMethodFrame_1OBJ: 000000ef180fd0b8] System.Threading.WaitHandle.WaitOneNative(System.Runtime.InteropServices.SafeHandle, UInt32, Boolean, Boolean)
000000ef180fd1e0 00007ffce4e2ddfc System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle, Int64, Boolean, Boolean)
000000ef180fd210 00007ffce4e2ddcf System.Threading.WaitHandle.WaitOne(Int32, Boolean)
000000ef180fd250 00007ffcb5573d74 System.Windows.Forms.Control.WaitForWaitHandle(System.Threading.WaitHandle)
000000ef180fd2c0 00007ffcb4dc0d54 System.Windows.Forms.Control.MarshaledInvoke(System.Windows.Forms.Control, System.Delegate, System.Object[], Boolean)
000000ef180fd400 00007ffcb5577674 System.Windows.Forms.Control.Invoke(System.Delegate, System.Object[])
000000ef180fd470 00007ffc882040d4 xxxx.backgroundWorker_ProgressChanged(System.Object, System.ComponentModel.ProgressChangedEventArgs)
000000ef180fe060 00007ffce4e1ae56 System.Threading.ThreadPoolWorkQueue.Dispatch() 

OS Thread Id: 0x4528 (101)
        Child SP               IP Call Site
000000ef183fe1d8 00007ffd01a4dc04 [HelperMethodFrame_1OBJ: 000000ef183fe1d8] System.Threading.WaitHandle.WaitOneNative(System.Runtime.InteropServices.SafeHandle, UInt32, Boolean, Boolean)
000000ef183fe300 00007ffce4e2ddfc System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle, Int64, Boolean, Boolean)
000000ef183fe330 00007ffce4e2ddcf System.Threading.WaitHandle.WaitOne(Int32, Boolean)
000000ef183fe370 00007ffcb5573d74 System.Windows.Forms.Control.WaitForWaitHandle(System.Threading.WaitHandle)
000000ef183fe3e0 00007ffcb4dc0d54 System.Windows.Forms.Control.MarshaledInvoke(System.Windows.Forms.Control, System.Delegate, System.Object[], Boolean)
000000ef183fe520 00007ffcb5577674 System.Windows.Forms.Control.Invoke(System.Delegate, System.Object[])
000000ef183fe590 00007ffc882040d4 xxxx.backgroundWorker_ProgressChanged(System.Object, System.ComponentModel.
000000ef183ff180 00007ffce4e1ae56 System.Threading.ThreadPoolWorkQueue.Dispatch() 
000000ef183ff608 00007ffce66112c3 [DebuggerU2MCatchHandlerFrame: 000000ef183ff608] 
...

观察上面的线程栈之后，发现有两个线程在 MarshaledInvoke 上等待，而且都是 backgroundWorker_ProgressChanged 方法，看样子有一个 backgroundWorker 控件在这里，其实这个信息还是值得警惕的，为什么这么说呢？因为它往往会预示着这个 Control 的 Queue 队列可能有很多的数据积压，那就往这个方向走。

3. Queue 队列有积压吗

要找到这个答案，需要观察主线程的线程栈上是否有 Queue 队列。


0:000> !dso
OS Thread Id: 0x918 (0)
RSP/REG          Object           Name
r13              000002a70660a860 System.Drawing.StringFormat
...
000000EF11D1D9B0 000002a7008b5a18 System.ComponentModel.BackgroundWorker
...
000000EF11D1E328 000002a7004ea8b8 System.Collections.Queue
...
0:000> !do 000002a7004ea8b8
Name:        System.Collections.Queue
MethodTable: 00007ffce48cd9d0
EEClass:     00007ffce49f5fd0
Size:        56(0x38) bytes
File:        C:\WINDOWS\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ffce48d0ba0  40018c3        8      System.Object[]  0 instance 000002a7039d3278 _array
00007ffce48d32c0  40018c4       18         System.Int32  1 instance              103 _head
00007ffce48d32c0  40018c5       1c         System.Int32  1 instance               74 _tail
00007ffce48d32c0  40018c6       20         System.Int32  1 instance              227 _size
00007ffce48d32c0  40018c7       24         System.Int32  1 instance              200 _growFactor
00007ffce48d32c0  40018c8       28         System.Int32  1 instance             1366 _version
00007ffce48d0b08  40018c9       10        System.Object  0 instance 0000000000000000 _syncRoot

从卦中数据看，这个 BackgroundWorker.Queue 当前有 227 个任务在队列积压，这说明主线程是没有问题的，只不过是在忙碌的处理任务而已，再回答最后一个问题，为什么会卡一阵子？

4. 为什么会卡一阵子

这是朋友提到的一个疑问，要想找到这个问题的答案，我们再回头看下主线程，看下它是如何从 Queue 中取数据的。


0:000> !clrstack
OS Thread Id: 0x918 (0)
        Child SP               IP Call Site
000000ef11d1cd70 00007ffd01a007b8 [InlinedCallFrame: 000000ef11d1cd70] System.Drawing.SafeNativeMethods+Gdip.GdipCreateStringFormat(System.Drawing.StringFormatFlags, Int32, IntPtr ByRef)
...
000000ef11d1d970 00007ffc87911aac xxx.backgroundWorker_ProgressChanged(System.Object, System.ComponentModel.ProgressChangedEventArgs)
000000ef11d1d9e0 00007ffcdeab652b System.ComponentModel.BackgroundWorker.OnProgressChanged(System.ComponentModel.ProgressChangedEventArgs)
000000ef11d1dc30 00007ffce66112c3 [DebuggerU2MCatchHandlerFrame: 000000ef11d1dc30] 
000000ef11d1dea8 00007ffce66112c3 [HelperMethodFrame_PROTECTOBJ: 000000ef11d1dea8] System.RuntimeMethodHandle.InvokeMethod(System.Object, System.Object[], System.Signature, Boolean)
000000ef11d1e020 00007ffce4dfcf58 System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(System.Object, System.Object[], System.Object[])
000000ef11d1e080 00007ffce4dcbd20 System.Delegate.DynamicInvokeImpl(System.Object[])
000000ef11d1e0d0 00007ffcb4dc702d System.Windows.Forms.Control.InvokeMarshaledCallbackDo(ThreadMethodEntry)
000000ef11d1e110 00007ffcb4dc6f49 System.Windows.Forms.Control.InvokeMarshaledCallbackHelper(System.Object)
000000ef11d1e160 00007ffce4ddfbe8 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000ef11d1e230 00007ffce4ddfad5 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000ef11d1e260 00007ffce4ddfaa5 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000ef11d1e2b0 00007ffcb4dc6ecc System.Windows.Forms.Control.InvokeMarshaledCallback(ThreadMethodEntry)
000000ef11d1e300 00007ffcb4dc6c36 System.Windows.Forms.Control.InvokeMarshaledCallbacks()
000000ef11d1e370 00007ffcb4db06fb System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)
000000ef11d1e430 00007ffcb4dafa72 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)
000000ef11d1e4d0 00007ffcb553d682 DomainBoundILStubClass.IL_STUB_ReversePInvoke(Int64, Int32, Int64, Int64)
000000ef11d1e810 00007ffce660fc9e [InlinedCallFrame: 000000ef11d1e810] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)
...
000000ef11d1ea30 00007ffcb4dc5982 System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)
000000ef11d1ecd0 00007ffc86e308e0 xxx.Program.Main(System.String[])
000000ef11d1ef08 00007ffce66112c3 [GCFrame: 000000ef11d1ef08]

从卦中看，线程栈上的 InvokeMarshaledCallback 方法就是取数据的函数，接下来用 ILSpy 反编译下这段代码，简化后如下：


private void InvokeMarshaledCallbacks()
{
	ThreadMethodEntry threadMethodEntry = null;
	lock(threadCallbackList)
	{
		if (threadCallbackList.Count > 0)
		{
			threadMethodEntry = (ThreadMethodEntry)threadCallbackList.Dequeue();
		}
	}
	while (threadMethodEntry != null)
	{
		try
		{
			InvokeMarshaledCallback(threadMethodEntry);
		}
		catch (Exception ex)
		{
			threadMethodEntry.exception = ex.GetBaseException();
		}

		lock(threadCallbackList)
		{
			threadMethodEntry = ((threadCallbackList.Count <= 0) ? null : ((ThreadMethodEntry)threadCallbackList.Dequeue()));
		}
	}
}

从代码中的while true来看，这方法真的很轴，不懂得变通，要么不取，要么就是一次性的取完，当 Queue=threadCallbackList 中的数据较多时，主线程就会非常的忙碌，所以这就是卡死一阵子的真正底层原因。

有了前因后果之后，建议朋友做如下两点修改：

Invoke 的逻辑尽量简单，让 UI 可以秒杀。
Invoke 的逻辑是否可以批量化，来减少 Queue 的积压。

三：总结

这次朋友的生产事故，对我们做分析的人来说还是有很大的教训意义，有时候主线程的一些抛错或者阻塞假象会诱导我们陷入分析误区，这就需要调试人员具有一双慧眼识别，及时的浪子回头。
图片名称