記一次 .NET 某物管後臺服務卡死分析

一：背景

1. 講故事

這幾個月經常被朋友問，為什麼不更新這個系列了，哈哈，確實停了好久，主要還是打基礎去了，分析 dump 的能力不在於會靈活使用 windbg，而是對底層知識有一個深厚的理解，比如：組合，C， C++，Win32 Api，虛擬記憶體，Windows 使用者態和核心態，這是我今年看的書給大家分享一下。

前段時候微信上有位朋友說他的程式出現了卡死，所有執行緒都不工作了，聽起來還挺嚇人的，截圖如下：

接下來直接上 WinDbg 分析吧。

二：Windbg 分析

1. 卡死分析

既然說程式所有執行緒都不工作了，大概率應該是此時 GC 觸發了，曾經看過一個dump中 GC 在建立 background thread 時，由於 dllmain 的死鎖造成了 background thread 無法生成引發的死鎖問題。

有了這個思路，接下來用 ~* k 看一下所有的執行緒棧，是否有GarbageCollectGeneration 函數，因為它是 GC 觸發入口點, 果然不出所料，46號執行緒觸發了 GC 操作。


  46  Id: 396c.3198 Suspend: 0 Teb: 00007ff6`22646000 Unfrozen
 # Child-SP          RetAddr               Call Site
00 00000028`d420bc18 00007ffa`8b6b8b61     ntdll!NtWaitForSingleObject+0xa
01 00000028`d420bc20 00007ffa`8b6b7124     ntdll!RtlpWaitOnCriticalSection+0xe1
02 00000028`d420bcf0 00000001`8000a725     ntdll!RtlpEnterCriticalSectionContended+0xa4
03 00000028`d420bd30 00000001`80011773     WiseVectorHelperOne_X64+0xa725
04 00000028`d420bd90 00007ffa`888faf8f     WiseVectorHelperOne_X64+0x11773
05 00000028`d420d2d0 00007ffa`79db4d45     KERNELBASE!ResumeThread+0xf
06 00000028`d420d300 00007ffa`79db8bee     coreclr!Thread::ResumeThread+0x29 [d:\a\_work\1\s\src\vm\threadsuspend.cpp @ 466] 
07 00000028`d420d350 00007ffa`79e13905     coreclr!ThreadSuspend::SuspendRuntime+0x17a [d:\a\_work\1\s\src\vm\threadsuspend.cpp @ 4046] 
08 00000028`d420d420 00007ffa`79db61cf     coreclr!ThreadSuspend::SuspendEE+0x16d [d:\a\_work\1\s\src\vm\threadsuspend.cpp @ 6517] 
09 (Inline Function) --------`--------     coreclr!GCToEEInterface::SuspendEE+0x21 [d:\a\_work\1\s\src\vm\gcenv.ee.cpp @ 25] 
0a 00000028`d420d5c0 00007ffa`79e325be     coreclr!WKS::GCHeap::GarbageCollectGeneration+0xff [d:\a\_work\1\s\src\gc\gc.cpp @ 36545] 
0b (Inline Function) --------`--------     coreclr!WKS::gc_heap::trigger_gc_for_alloc+0x12 [d:\a\_work\1\s\src\gc\gc.cpp @ 13832] 
0c 00000028`d420d610 00007ffa`79e35118     coreclr!WKS::gc_heap::try_allocate_more_space+0x24e [d:\a\_work\1\s\src\gc\gc.cpp @ 13934] 
0d (Inline Function) --------`--------     coreclr!WKS::gc_heap::allocate_more_space+0x11 [d:\a\_work\1\s\src\gc\gc.cpp @ 14369] 
0e (Inline Function) --------`--------     coreclr!WKS::gc_heap::allocate+0x58 [d:\a\_work\1\s\src\gc\gc.cpp @ 14400] 
0f 00000028`d420d690 00007ffa`79dcda8e     coreclr!WKS::GCHeap::Alloc+0x88 [d:\a\_work\1\s\src\gc\gc.cpp @ 35827]

從執行緒棧看，流程大概是： C# 分配一個物件，觸發了 GC，然後暫停了所有託管執行緒，然後又恢復了其中一個執行緒，應該是此執行緒沒有停留在 gc 安全點上，重啟是為了讓它在安全點暫停，在 coreclr 原始碼上也能看的出來。

接下來就進入了 WiseVectorHelperOne_X64 類庫，很陌生的一個 dll，最後進入了 臨界區 CriticalSection ，所謂的 臨界區 是一個 win32 函數，用法和我們的 lock 差不多，最後就停留在臨界區，其實到這裡現象就很明朗了，所有的託管執行緒都暫停了，也符合朋友說的程式卡死，接下來就要分析為什麼程式退不出 臨界區 ？

2. 為啥退不出 CriticalSection

要想尋找這個答案，可以用 !locks 來觀察當前處於 臨界區 的執行緒，輸出如下：


0:000> !locks

CritSec +63218af0 at 0000002863218af0
WaiterWoken        No
LockCount          0
RecursionCount     1
OwningThread       3198
EntryCount         0
ContentionCount    16d
*** Locked

CritSec WiseVectorHelperOne_X64+6a9a8 at 000000018006a9a8
WaiterWoken        No
LockCount          1
RecursionCount     1
OwningThread       3090
EntryCount         0
ContentionCount    1
*** Locked

Scanned 64 critical sections

根據經驗，第一反應應該是 臨界區死鎖 了，經驗歸經驗，接下來我們依次看下 3198 和 3090 各自都在等什麼？

3. 真的是臨界區死鎖嗎

首先用命令切到 3198 執行緒，看看它正在等待什麼資源？


0:038>  ~~[3198]s
ntdll!NtWaitForSingleObject+0xa:
00007ffa`8b710c8a c3              ret
0:046> kb
 # RetAddr               : Args to Child                                                           : Call Site
00 00007ffa`8b6b8b61     : 00000001`8006a9a8 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!NtWaitForSingleObject+0xa
01 00007ffa`8b6b7124     : 00000000`00000000 00000000`00000000 00000001`8006a9a8 00000000`00000000 : ntdll!RtlpWaitOnCriticalSection+0xe1
02 00000001`8000a725     : 00000028`00668230 00000000`00000000 00000028`7fc9d9b0 00000028`00668230 : ntdll!RtlpEnterCriticalSectionContended+0xa4
03 00000001`80011773     : 00000001`00000aa8 00000000`00000000 00000000`00000000 00000000`00000000 : WiseVectorHelperOne_X64+0xa725
04 00007ffa`888faf8f     : 00000000`00000aa8 00000028`d420d308 00000000`00000000 00000000`00000000 : WiseVectorHelperOne_X64+0x11773
05 00007ffa`79db4d45     : 00000000`00000000 00000000`00000000 00000028`04dec6e0 00000001`8000cc3a : KERNELBASE!ResumeThread+0xf
06 00007ffa`79db8bee     : 00000028`00668230 00000000`00000040 00000000`00000001 00000000`00000000 : coreclr!Thread::ResumeThread+0x29 [d:\a\_work\1\s\src\vm\threadsuspend.cpp @ 466] 
07 00007ffa`79e13905     : 00000000`00000003 00000000`00000001 00000000`00000001 00000000`00000000 : coreclr!ThreadSuspend::SuspendRuntime+0x17a [d:\a\_work\1\s\src\vm\threadsuspend.cpp @ 4046] 
08 00007ffa`79db61cf     : 00000000`00001e73 00000000`00001e01 00000028`7f9f6698 00000000`00000000 : coreclr!ThreadSuspend::SuspendEE+0x16d [d:\a\_work\1\s\src\vm\threadsuspend.cpp @ 6517] 
09 (Inline Function)     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!GCToEEInterface::SuspendEE+0x21 [d:\a\_work\1\s\src\vm\gcenv.ee.cpp @ 25] 
0a 00007ffa`79e325be     : a2098c12`cdff0000 00007ffa`79e35118 00007ffa`7a28c668 00000000`00000000 : coreclr!WKS::GCHeap::GarbageCollectGeneration+0xff [d:\a\_work\1\s\src\gc\gc.cpp @ 36545] 
0b (Inline Function)     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!WKS::gc_heap::trigger_gc_for_alloc+0x12 [d:\a\_work\1\s\src\gc\gc.cpp @ 13832] 
0c 00007ffa`79e35118     : 00000028`7fc9da08 00000028`12bba6d8 00000000`00000002 00007ffa`79dbfc9f : coreclr!WKS::gc_heap::try_allocate_more_space+0x24e [d:\a\_work\1\s\src\gc\gc.cpp @ 13934] 
0d (Inline Function)     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!WKS::gc_heap::allocate_more_space+0x11 [d:\a\_work\1\s\src\gc\gc.cpp @ 14369] 
0e (Inline Function)     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!WKS::gc_heap::allocate+0x58 [d:\a\_work\1\s\src\gc\gc.cpp @ 14400] 
0f 00007ffa`79dcda8e     : 00000000`00000000 00000028`d420daa0 00007ffa`1a908888 00000028`7fc9da08 : coreclr!WKS::GCHeap::Alloc+0x88 [d:\a\_work\1\s\src\gc\gc.cpp @ 35827] 
10 (Inline Function)     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!Alloc+0x18b [d:\a\_work\1\s\src\vm\gchelpers.cpp @ 240] 
11 (Inline Function)     : --------`-------- --------`-------- --------`-------- --------`-------- : coreclr!AllocateObject+0x22d [d:\a\_work\1\s\src\vm\gchelpers.cpp @ 1209] 
12 00007ffa`1b3337e2     : 00007ffa`1a908888 00000028`84d75cc0 00000028`12bb9ce0 00000028`64df1360 : coreclr!JIT_New+0x31e [d:\a\_work\1\s\src\vm\jithelpers.cpp @ 2724] 
....

從輸出資訊看: NtWaitForSingleObject 正在等待 000000018006a9a8 臨界區資源，而這個正好是 !locks 的 3090 執行緒持有的資源，截圖如下：

接下來再看下 3090 執行緒正在幹什麼。


0:038> ~~[3090]s
WiseVectorHelperOne_X64+0xcc3a:
00000001`8000cc3a 4889442408      mov     qword ptr [rsp+8],rax ss:00000028`04dec6e8=0000000000000000
0:038> k
 # Child-SP          RetAddr               Call Site
00 00000028`04dec6e0 00000001`8000f1cb     WiseVectorHelperOne_X64+0xcc3a
01 00000028`04dec710 00000001`8000a751     WiseVectorHelperOne_X64+0xf1cb
02 00000028`04dec7a0 00000001`80011773     WiseVectorHelperOne_X64+0xa751
03 00000028`04dec800 00007ffa`888faf8f     WiseVectorHelperOne_X64+0x11773
04 00000028`04dedd40 00007ffa`79e19796     KERNELBASE!ResumeThread+0xf
05 (Inline Function) --------`--------     coreclr!Thread::StartThread+0x15 [d:\a\_work\1\s\src\vm\threads.cpp @ 528] 
06 00000028`04dedd70 00007ffa`79eaacea     coreclr!ThreadNative::StartInner+0x35a [d:\a\_work\1\s\src\vm\comsynchronizable.cpp @ 501] 
07 00000028`04dee010 00007ffa`1b3afc02     coreclr!ThreadNative::Start+0x8a [d:\a\_work\1\s\src\vm\comsynchronizable.cpp @ 387] 
08 00000028`04dee160 00007ffa`1b3cb018     System_Private_CoreLib!System.Threading.Tasks.Task.ScheduleAndStart+0x102
09 00000028`04dee1b0 00007ffa`1b40005a     System_Private_CoreLib!System.Threading.Tasks.Task.InternalStartNew+0x78
0a 00000028`04dee230 00007ffa`1b41f181     System_Private_CoreLib!System.Threading.Tasks.TaskFactory.StartNew+0x5a
...

從執行緒棧資訊看，託管層執行了一個 Task.Start 操作，然後通過 Win32 Api 生成了一個 OS 執行緒，在準備排程 OS執行緒 的時候，遇上了 WiseVectorHelperOne_X64 ，最後就在這裡無限期等待，tmd的真奇怪，在兩個執行緒中都看到了這個函數，它到底是幹嘛呢？

4. 研究 WiseVectorHelperOne_X64

這個奇怪的 dll，看樣子來者不善，上 baidu 查檢視。

我去，原來被一款叫做 智量防毒軟體 給劫持了。。。具體什麼原因被劫持，我也不想研究了，然後拿這個結果和朋友做了一下溝通，嘗試停掉它看看。

三：總結

綜合兩處執行緒棧的特徵，發現都是Win32 Api 在做 Thread::ResumeThread 時被防毒軟體劫持，一般來說 clr 在內部生成 OS 執行緒時，會先 Suspended，然後再 Resume，參考原始碼：


BOOL Thread::CreateNewOSThread(SIZE_T sizeToCommitOrReserve, LPTHREAD_START_ROUTINE start, void* args)
{
    HANDLE h = NULL;
    DWORD dwCreationFlags = CREATE_SUSPENDED;

    dwCreationFlags |= STACK_SIZE_PARAM_IS_A_RESERVATION;

    h = ::CreateThread(NULL     /*=SECURITY_ATTRIBUTES*/,

                             sizeToCommitOrReserve,
                             start,
                             args,
                             dwCreationFlags,
                             &ourId);
}

劫持的原因，這個只能問廠家了，我們能做的就是停掉它

記一次 .NET 某物管後臺服務 卡死分析