一:背景 1. 講故事 前些天有位朋友找到我,說他們的程式會偶發性的卡死一段時間,然後又好了,讓我幫忙看下怎麼回事?窗體類的程式解決起來相對來說比較簡單,讓朋友用procdump自動抓一個卡死時的dump,拿到dump之後,上 windbg 說話。 二:WinDbg 分析 1. 主線程在做什麼 要想 ...
一:背景
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 的積壓。
三:總結
這次朋友的生產事故,對我們做分析的人來說還是有很大的教訓意義,有時候主線程的一些拋錯或者阻塞假象會誘導我們陷入分析誤區,這就需要調試人員具有一雙慧眼識別,及時的浪子回頭。