记一次 .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
...
11 00000000`007fe230 00007ffc`7cdc2df6 combase!DefaultStubInvoke+0x1c4
12 (Inline Function) --------`-------- combase!SyncStubCall::Invoke+0x22
13 00000000`007fe380 00007ffc`7cd62e55 combase!SyncServerCall::StubInvoke+0x26
14 (Inline Function) --------`-------- combase!StubInvoke+0x265
15 00000000`007fe3c0 00007ffc`7cd8ded2 combase!ServerCall::ContextInvoke+0x435
...
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 , 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
KERNELBASE!SleepEx:
00007ffc`79a15590 89542410 mov dword ptr , 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
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 , rcx
00007ffc`79a15615 48f7d9 neg rcx
...
00007ffc`79a15622 488d542420 lea rdx,
00007ffc`79a15627 0fb6cb movzx ecx, bl
00007ffc`79a1562a 48ff15ef641400 call qword ptr 再上一段 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=00000000007fd628r9=00000000bf1efcf8 r10=0000000000000000
r11=0000000000000246 r12=0000000000000000 r13=0000000000000798
r14=000000003bd064b0 r15=00000000bf1efce0
0:000> dp 00000000007fd650 L1
00000000`007fd650ffffffff`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 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 根据卦中的托管方法 xxxx.SetDefaultRecord() ，让朋友不要做 Image 赋值观察下效果，朋友反馈说，这个 Image 不赋值问题就没有了。
既然去掉就好了，到这里只能推测当前主线程不是卡死，而是 RPC 请求过多Size过大，导致主线程一直忙碌中，具体为什么会忙碌，这就需要逆向 cogxstd 来滤清业务逻辑了，这个就太费时费力了，还是先绕过去为好。
三：总结
还是回到文章开头的那句话，这种 dump 问题，你能用 DnSpy，VS 调试出来吗？说实话很难，虽然以 .NET 程序为出口，但考察了你很多基础知识，诸如 RPC，COM，汇编，没有这些基础沉淀，这类dump很难摸清来龙去脉。
来源:https://www.cnblogs.com/huangxincheng/archive/2023/07/04/17525483.html
免责声明：由于采集信息均来自互联网，如果侵犯了您的权益，请联系我们【E-Mail:cb@itdo.tech】 我们会及时删除侵权内容，谢谢合作！
页:
[1]