記一次 .NET 某工控視覺系統卡死分析

一：背景

1. 講故事

前段時間有位朋友找到我，說他們的工業視覺軟體僵死了，讓我幫忙看下到底是什麼情況，哈哈，其實卡死的問題相對好定位，無非就是看主執行緒棧嘛，然後就是具體問題具體分析，當然難度大小就看運氣了。

前幾天看一篇文章說現在的 .NET程式設計師不需要學習WinDbg ，理由就是有很多好的分析工具諸如 VS，DnSpy，PerfView 可以替代，我也只能笑笑，在他們的認知中可能 .NET程式 是不需要和其他語言互動而獨成一體的。

話不多說，回到主題，上 WinDbg 說話。

二：為什麼會卡死

1. 主執行緒在做什麼

剛才也說到了，卡死是比較好定位的，切到主執行緒看執行緒棧即可,簡化輸出如下：


0:000> ~0s;k
ntdll!NtDelayExecution+0x14:
00007ffc`7d45fcf4 c3              ret
 # Child-SP          RetAddr               Call Site
00 00000000`007fd628 00007ffc`79a15631     ntdll!NtDelayExecution+0x14
01 00000000`007fd630 00007ffc`40b7b116     KERNELBASE!SleepEx+0xa1
02 00000000`007fd6d0 00007ffc`40b7372e     cogxstd+0x13b116
03 00000000`007fd700 00007ffc`40b73ece     cogxstd+0x13372e
...
09 00000000`007fd9b0 00007ffc`7d1c77e3     CogDisplay!DllUnregisterServer+0x1833f
0a 00000000`007fdab0 00007ffc`7d16436c     rpcrt4!Invoke+0x73
0b 00000000`007fdb00 00007ffc`7cdbc473     rpcrt4!NdrStubCall2+0x42c
0c 00000000`007fe130 00007ffc`7c451bf0     combase!CStdStubBuffer_Invoke+0x73 [onecore\com\combase\ndr\ndrole\stub.cxx @ 1446] 
...
11 00000000`007fe230 00007ffc`7cdc2df6     combase!DefaultStubInvoke+0x1c4 [onecore\com\combase\dcomrem\channelb.cxx @ 1769] 
12 (Inline Function) --------`--------     combase!SyncStubCall::Invoke+0x22 [onecore\com\combase\dcomrem\channelb.cxx @ 1826] 
13 00000000`007fe380 00007ffc`7cd62e55     combase!SyncServerCall::StubInvoke+0x26 [onecore\com\combase\dcomrem\servercall.hpp @ 825] 
14 (Inline Function) --------`--------     combase!StubInvoke+0x265 [onecore\com\combase\dcomrem\channelb.cxx @ 2052] 
15 00000000`007fe3c0 00007ffc`7cd8ded2     combase!ServerCall::ContextInvoke+0x435 [onecore\com\combase\dcomrem\ctxchnl.cxx @ 1532] 
...
31 00000000`007fff60 00000000`00000000     ntdll!RtlUserThreadStart+0x21

從卦中看當前主執行緒正在 Sleep，這就很奇葩了，並且還是康耐視的 cogxstd 動態連結庫的邏輯，這裡我敢相信它不會有這麼低階的錯誤，接下來我們洞察下到底 Sleep 了多久，仔細觀察組合程式碼，精簡後如下：


    ntdll!NtDelayExecution:
00007ffc`7d45fce0 4c8bd1           mov     r10, rcx
00007ffc`7d45fce3 b834000000       mov     eax, 34h
00007ffc`7d45fce8 f604250803fe7f01 test    byte ptr [7FFE0308h], 1
00007ffc`7d45fcf0 7503             jne     ntdll!NtDelayExecution+0x15 (7ffc7d45fcf5)
00007ffc`7d45fcf2 0f05             syscall 
00007ffc`7d45fcf4 c3               ret     
00007ffc`7d45fcf5 cd2e             int     2Eh
00007ffc`7d45fcf7 c3               ret     
00007ffc`7d45fcf8 0f1f840000000000 nop     dword ptr [rax+rax]

    KERNELBASE!SleepEx:
00007ffc`79a15590 89542410         mov     dword ptr [rsp+10h], edx
00007ffc`79a15594 4c8bdc           mov     r11, rsp
00007ffc`79a15597 53               push    rbx
00007ffc`79a15598 56               push    rsi
00007ffc`79a15599 57               push    rdi
00007ffc`79a1559a 4881ec80000000   sub     rsp, 80h
00007ffc`79a155a1 8bda             mov     ebx, edx
00007ffc`79a155a3 8bf9             mov     edi, ecx
...
00007ffc`79a155f4 488b9424b8000000 mov     rdx, qword ptr [rsp+0B8h]
00007ffc`79a155fc 85db             test    ebx, ebx
00007ffc`79a155fe 0f8592000000     jne     KERNELBASE!SleepEx+0x106 (7ffc79a15696)
00007ffc`79a15604 83ffff           cmp     edi, 0FFFFFFFFh
00007ffc`79a15607 7443             je      KERNELBASE!SleepEx+0xbc (7ffc79a1564c)
00007ffc`79a15609 4869cf10270000   imul    rcx, rdi, 2710h
00007ffc`79a15610 48894c2420       mov     qword ptr [rsp+20h], rcx
00007ffc`79a15615 48f7d9           neg     rcx
...
00007ffc`79a15622 488d542420       lea     rdx, [rsp+20h]
00007ffc`79a15627 0fb6cb           movzx   ecx, bl
00007ffc`79a1562a 48ff15ef641400   call    qword ptr [KERNELBASE!__imp_NtDelayExecution (7ffc79b5bb20)]

再上一段 reactos 的 C++ 方法簽名。


DWORD
WINAPI
SleepEx(IN DWORD dwMilliseconds,
        IN BOOL bAlertable)
{}

NTSTATUS
NTAPI
NtDelayExecution(IN BOOLEAN Alertable,
                 IN PLARGE_INTEGER DelayInterval)
{}

我們要重點觀察 NtDelayExecution 方法中 rdx 引數是怎麼計算的，重點就是下面的兩句組合。


imul    rcx, rdi, 2710h
neg     rcx

這兩句組合是什麼意思呢？轉成 C++ 程式碼就是


interval = - (milliseconds * 0x2710);

在組合中我們是知道 interval 的，它相當於是 milliseconds 計算後的二補數，即下面的 Binary: 列。


0:000> r
rax=0000000000000034 rbx=0000000000000000 rcx=0000000000000000
rdx=00000000007fd650 rsi=0000000000000000 rdi=0000000000000001
rip=00007ffc7d45fcf4 rsp=00000000007fd628 rbp=00000000bf1efcf8
 r8=00000000007fd628  r9=00000000bf1efcf8 r10=0000000000000000
r11=0000000000000246 r12=0000000000000000 r13=0000000000000798
r14=000000003bd064b0 r15=00000000bf1efce0

0:000> dp 00000000007fd650 L1
00000000`007fd650  ffffffff`ffffd8f0

0:000> .formats ffffffff`ffffd8f0
Evaluate expression:
  Hex:     ffffffff`ffffd8f0
  Binary:  11111111 11111111 11111111 11111111 11111111 11111111 11011000 11110000
  ...

那怎麼求 milliseconds 呢？其實 二補數的二補數 就是原碼，然後再除以 0x2710 就可以獲取到 milliseconds 了哈。

二補數：11111111 11111111 11111111 11111111 11111111 11111111 11011000 11110000
反碼：00000000 00000000 00000000 00000000 00000000 00000000 00100111 00001111
補補：00000000 00000000 00000000 00000000 00000000 00000000 00100111 00010000


0:000> .formats 0y0000000000000000000000000000000000000000000000000010011100010000
Evaluate expression:
  Hex:     00000000`00002710
  Decimal: 10000
  Decimal (unsigned) : 10000
  Octal:   0000000000000000023420
  Binary:  00000000 00000000 00000000 00000000 00000000 00000000 00100111 00010000

0:000> ? 00002710/ 2710
Evaluate expression: 1 = 00000000`00000001

從卦中看當前也就暫停了 1ms，如果想驗證對不對的話，仔細看mov edi, ecx 會發現做了一次備份，但不管怎麼說 Thread.Sleep(1) 應該問題不大，那問題在哪裡呢？

2. 問題到底在哪裡

既然問題不在 Sleep(1) 上那到底在哪裡呢？仔細觀察執行緒棧會發現底層做了一個 RPC 通訊，從 combase!SyncServerCall::StubInvoke 和 rpcrt4!NdrStubCall2 方法來看，它是 RPC 的 Server 端，既然是 Server 端就必然有 Client 端，根據經驗這個 RPC 應該是 命令管道 的方式，沒開 Windows 的RPC診斷所以不能100%確認。

接下來看下其他執行緒有沒有 RPC 的 rpcrt4!NdrpClientCall 請求，抱著試試看的態度搜一搜，我去，還真有10幾個，截圖如下：

仔細分析這 12 個 Reqeust，發現其中的 Cognex.VisionPro.Display.CogDisplay.set_Image 比較可疑，畢竟 Image 運作起來肯定是費時費力的。


0:543> k
 # Child-SP          RetAddr               Call Site
00 00000000`fc65def8 00007ffc`79a1c2ce     ntdll!NtWaitForMultipleObjects+0x14
...
04 (Inline Function) --------`--------     combase!CSyncClientCall::SwitchAptAndDispatchCall+0x34a
05 00000000`fc65e290 00007ffc`7cd9b015     combase!CSyncClientCall::SendReceive2+0x42c
06 (Inline Function) --------`--------     combase!SyncClientCallRetryContext::SendReceiveWithRetry+0x25 
07 (Inline Function) --------`--------     combase!CSyncClientCall::SendReceiveInRetryContext+0x25 
08 00000000`fc65e480 00007ffc`7cd8c55d     combase!DefaultSendReceive+0x65
09 00000000`fc65e4e0 00007ffc`7cd60a54     combase!CSyncClientCall::SendReceive+0x12d 
0a 00000000`fc65e710 00007ffc`7cdbc54e     combase!CClientChannel::SendReceive+0x84 
0b 00000000`fc65e780 00007ffc`7d151e93     combase!NdrExtpProxySendReceive+0x4e 
0c 00000000`fc65e7b0 00007ffc`7cdbae17     rpcrt4!NdrpClientCall2+0x463
0d 00000000`fc65edf0 00007ffc`7ce2ce92     combase!ObjectStublessClient+0x1d7 
0e 00000000`fc65f180 00007ffb`f1321db8     combase!ObjectStubless+0x42
0f 00000000`fc65f1d0 00007ffc`4002c906     0x00007ffb`f1321db8
10 00000000`fc65f2c0 00007ffb`f131d541     Cognex_VisionPro_Display_Controls_ni!Cognex.VisionPro.Display.CogDisplay.set_Image+0xb6

0:543> !clrstack
OS Thread Id: 0x2bbc (543)
        Child SP               IP Call Site
...
00000000fc65f208 00007ffbf1321db8 [InlinedCallFrame: 00000000fc65f208] Cognex.VisionPro.Interop.CogDisplayClass.set_Image(Cognex.VisionPro.Interop.ICogImage)
00000000fc65f1d0 00007ffbf1321db8 DomainBoundILStubClass.IL_STUB_CLRtoCOM(Cognex.VisionPro.Interop.ICogImage)
00000000fc65f2c0 00007ffc4002c906 Cognex.VisionPro.Display.CogDisplay.set_Image(Cognex.VisionPro.ICogImage)
00000000fc65f310 00007ffbf131d541 xxxx.SetDefaultRecord()
...
00000000fc65f680 00007ffc4bc17e46 System.Threading.ThreadPoolWorkQueue.Dispatch()
00000000fc65fb20 00007ffc4d706c93 [DebuggerU2MCatchHandlerFrame: 00000000fc65fb20]

根據卦中的託管方法 xxxx.SetDefaultRecord() ，讓朋友不要做 Image 賦值觀察下效果，朋友反饋說，這個 Image 不賦值問題就沒有了。

既然去掉就好了，到這裡只能推測當前主執行緒不是卡死，而是 RPC 請求過多Size過大，導致主執行緒一直忙碌中，具體為什麼會忙碌，這就需要逆向 cogxstd 來濾清業務邏輯了，這個就太費時費力了，還是先繞過去為好。

三：總結

還是回到文章開頭的那句話，這種 dump 問題，你能用 DnSpy，VS 偵錯出來嗎？說實話很難，雖然以 .NET 程式為出口，但考察了你很多基礎知識，諸如 RPC，COM，組合，沒有這些基礎沉澱，這類dump很難摸清來龍去脈。