记一次 .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 来滤清业务逻辑了，这个就太费时费力了，还是先绕过去为好。