一：背景

1. 講故事

前段時間有位朋友找到我，說他們的工業(yè)視覺軟件僵死了，讓我?guī)兔聪碌降资鞘裁辞闆r，哈哈，其實卡死的問題相對好定位，無非就是看主線程棧嘛，然后就是具體問題具體分析，當(dāng)然難度大小就看運氣了。

前幾天看一篇文章說現(xiàn)在的 .NET程序員不需要學(xué)習(xí)WinDbg ，理由就是有很多好的分析工具諸如 VS，DNSpy，PerfView 可以替代，我也只能笑笑，在他們的認(rèn)知中可能 .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 [onecorecomcombasendrndrolestub.cxx @ 1446] 
...
11 00000000`007fe230 00007ffc`7cdc2df6     combase!DefaultStubInvoke+0x1c4 [onecorecomcombasedcomremchannelb.cxx @ 1769] 
12 (Inline Function) --------`--------     combase!SyncStubCall::Invoke+0x22 [onecorecomcombasedcomremchannelb.cxx @ 1826] 
13 00000000`007fe380 00007ffc`7cd62e55     combase!SyncServerCall::StubInvoke+0x26 [onecorecomcombasedcomremservercall.hpp @ 825] 
14 (Inline Function) --------`--------     combase!StubInvoke+0x265 [onecorecomcombasedcomremchannelb.cxx @ 2052] 
15 00000000`007fe3c0 00007ffc`7cd8ded2     combase!ServerCall::ContextInvoke+0x435 [onecorecomcombasedcomremctxchnl.cxx @ 1532] 
...
31 00000000`007fff60 00000000`00000000     ntdll!RtlUserThreadStart+0x21

從卦中看當(dāng)前主線程正在 Sleep，這就很奇葩了，并且還是康耐視的 cogxstd 動態(tài)鏈接庫的邏輯，這里我敢相信它不會有這么低級的錯誤，接下來我們洞察下到底 Sleep 了多久，仔細(xì)觀察匯編代碼，精簡后如下：


    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 參數(shù)是怎么計算的，重點就是下面的兩句匯編。


imul    rcx, rdi, 2710h
neg     rcx

這兩句匯編是什么意思呢？轉(zhuǎn)成 C++ 代碼就是


interval = - (milliseconds * 0x2710);

在匯編中我們是知道 interval 的，它相當(dāng)于是 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

從卦中看當(dāng)前也就暫停了 1ms，如果想驗證對不對的話，仔細(xì)看mov edi, ecx 會發(fā)現(xiàn)做了一次備份，但不管怎么說 Thread.Sleep(1) 應(yīng)該問題不大，那問題在哪里呢？

2. 問題到底在哪里

既然問題不在 Sleep(1) 上那到底在哪里呢？仔細(xì)觀察線程棧會發(fā)現(xiàn)底層做了一個 RPC 通訊，從 combase!
SyncServerCall::StubInvoke 和 rpcrt4!NdrStubCall2 方法來看，它是 RPC 的 Server 端，既然是 Server 端就必然有 Client 端，根據(jù)經(jīng)驗這個 RPC 應(yīng)該是 命令管道 的方式，沒開 windows 的RPC診斷所以不能100%確認(rèn)。

接下來看下其他線程有沒有 RPC 的 rpcrt4!NdrpClientCall 請求，抱著試試看的態(tài)度搜一搜，我去，還真有10幾個，截圖如下：

仔細(xì)分析這 12 個 Reqeust，發(fā)現(xiàn)其中的
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]

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

既然去掉就好了，到這里只能推測當(dāng)前主線程不是卡死，而是 RPC 請求過多Size過大，導(dǎo)致主線程一直忙碌中，具體為什么會忙碌，這就需要逆向 cogxstd 來濾清業(yè)務(wù)邏輯了，這個就太費時費力了，還是先繞過去為好。