记一次 .NET 某工控视觉系统 卡死分析2023-07-04 13:40:58 | 来源：博客园 | 

一：背景1. 讲故事

前段时间有位朋友找到我，说他们的工业视觉软件僵死了，让我帮忙看下到底是什么情况，哈哈，其实卡死的问题相对好定位，无非就是看主线程栈嘛，然后就是具体问题具体分析，当然难度大小就看运气了。

(资料图片)

前几天看一篇文章说现在的 .NET程序员 不需要学习WinDbg，理由就是有很多好的分析工具诸如 VS，DnSpy，PerfView 可以替代，我也只能笑笑，在他们的认知中可能 .NET程序是不需要和其他语言交互而独成一体的。

话不多说，回到主题，上 WinDbg 说话。

二：为什么会卡死1. 主线程在做什么

刚才也说到了，卡死是比较好定位的，切到主线程看线程栈即可,简化输出如下：

0:000> ~0s;kntdll!NtDelayExecution+0x14:00007ffc`7d45fcf4 c3              ret # Child-SP          RetAddr               Call Site00 00000000`007fd628 00007ffc`79a15631     ntdll!NtDelayExecution+0x1401 00000000`007fd630 00007ffc`40b7b116     KERNELBASE!SleepEx+0xa102 00000000`007fd6d0 00007ffc`40b7372e     cogxstd+0x13b11603 00000000`007fd700 00007ffc`40b73ece     cogxstd+0x13372e...09 00000000`007fd9b0 00007ffc`7d1c77e3     CogDisplay!DllUnregisterServer+0x1833f0a 00000000`007fdab0 00007ffc`7d16436c     rpcrt4!Invoke+0x730b 00000000`007fdb00 00007ffc`7cdbc473     rpcrt4!NdrStubCall2+0x42c0c 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, rcx00007ffc`7d45fce3 b834000000       mov     eax, 34h00007ffc`7d45fce8 f604250803fe7f01 test    byte ptr [7FFE0308h], 100007ffc`7d45fcf0 7503             jne     ntdll!NtDelayExecution+0x15 (7ffc7d45fcf5)00007ffc`7d45fcf2 0f05             syscall 00007ffc`7d45fcf4 c3               ret     00007ffc`7d45fcf5 cd2e             int     2Eh00007ffc`7d45fcf7 c3               ret     00007ffc`7d45fcf8 0f1f840000000000 nop     dword ptr [rax+rax]    KERNELBASE!SleepEx:00007ffc`79a15590 89542410         mov     dword ptr [rsp+10h], edx00007ffc`79a15594 4c8bdc           mov     r11, rsp00007ffc`79a15597 53               push    rbx00007ffc`79a15598 56               push    rsi00007ffc`79a15599 57               push    rdi00007ffc`79a1559a 4881ec80000000   sub     rsp, 80h00007ffc`79a155a1 8bda             mov     ebx, edx00007ffc`79a155a3 8bf9             mov     edi, ecx...00007ffc`79a155f4 488b9424b8000000 mov     rdx, qword ptr [rsp+0B8h]00007ffc`79a155fc 85db             test    ebx, ebx00007ffc`79a155fe 0f8592000000     jne     KERNELBASE!SleepEx+0x106 (7ffc79a15696)00007ffc`79a15604 83ffff           cmp     edi, 0FFFFFFFFh00007ffc`79a15607 7443             je      KERNELBASE!SleepEx+0xbc (7ffc79a1564c)00007ffc`79a15609 4869cf10270000   imul    rcx, rdi, 2710h00007ffc`79a15610 48894c2420       mov     qword ptr [rsp+20h], rcx00007ffc`79a15615 48f7d9           neg     rcx...00007ffc`79a15622 488d542420       lea     rdx, [rsp+20h]00007ffc`79a15627 0fb6cb           movzx   ecx, bl00007ffc`79a1562a 48ff15ef641400   call    qword ptr [KERNELBASE!__imp_NtDelayExecution (7ffc79b5bb20)]

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

DWORDWINAPISleepEx(IN DWORD dwMilliseconds,        IN BOOL bAlertable){}NTSTATUSNTAPINtDelayExecution(IN BOOLEAN Alertable,                 IN PLARGE_INTEGER DelayInterval){}

我们要重点观察 NtDelayExecution方法中 rdx 参数是怎么计算的，重点就是下面的两句汇编。

imul    rcx, rdi, 2710hneg     rcx

这两句汇编是什么意思呢？ 转成 C++ 代码就是

interval = - (milliseconds * 0x2710);

在汇编中我们是知道 interval的，它相当于是 milliseconds 计算后的补码，即下面的 Binary:列。

0:000> rrax=0000000000000034 rbx=0000000000000000 rcx=0000000000000000rdx=00000000007fd650 rsi=0000000000000000 rdi=0000000000000001rip=00007ffc7d45fcf4 rsp=00000000007fd628 rbp=00000000bf1efcf8 r8=00000000007fd628  r9=00000000bf1efcf8 r10=0000000000000000r11=0000000000000246 r12=0000000000000000 r13=0000000000000798r14=000000003bd064b0 r15=00000000bf1efce00:000> dp 00000000007fd650 L100000000`007fd650  ffffffff`ffffd8f00:000> .formats ffffffff`ffffd8f0Evaluate 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 0y0000000000000000000000000000000000000000000000000010011100010000Evaluate expression:  Hex:     00000000`00002710  Decimal: 10000  Decimal (unsigned) : 10000  Octal:   0000000000000000023420  Binary:  00000000 00000000 00000000 00000000 00000000 00000000 00100111 000100000:000> ? 00002710/ 2710Evaluate 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 Site00 00000000`fc65def8 00007ffc`79a1c2ce     ntdll!NtWaitForMultipleObjects+0x14...04 (Inline Function) --------`--------     combase!CSyncClientCall::SwitchAptAndDispatchCall+0x34a05 00000000`fc65e290 00007ffc`7cd9b015     combase!CSyncClientCall::SendReceive2+0x42c06 (Inline Function) --------`--------     combase!SyncClientCallRetryContext::SendReceiveWithRetry+0x25 07 (Inline Function) --------`--------     combase!CSyncClientCall::SendReceiveInRetryContext+0x25 08 00000000`fc65e480 00007ffc`7cd8c55d     combase!DefaultSendReceive+0x6509 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+0x4630d 00000000`fc65edf0 00007ffc`7ce2ce92     combase!ObjectStublessClient+0x1d7 0e 00000000`fc65f180 00007ffb`f1321db8     combase!ObjectStubless+0x420f 00000000`fc65f1d0 00007ffc`4002c906     0x00007ffb`f1321db810 00000000`fc65f2c0 00007ffb`f131d541     Cognex_VisionPro_Display_Controls_ni!Cognex.VisionPro.Display.CogDisplay.set_Image+0xb60:543> !clrstackOS 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很难摸清来龙去脉。