记一次 NET某固高运动卡测试 卡慢分析

记一次 NET某固高运动卡测试 卡慢分析

记一次 NET某固高运动卡测试 卡慢分析

1. 讲故事

年前有位朋友找到我，说他们的程序会偶发性卡慢 10s 钟，在某些组合下会正常，某些组合下就会出现问题，解释不了其中的原因，让我帮忙看下怎么回事？截图如下： ``` private void TestRun() { int encposUpy = 0; Logger Log = new Logger(); Task.Factory.StartNew(delegate { Log.Info("GTN_GetEcatEncPos.上探头Y------start。"); while (runFlag) { Log.Info("GTN_GetEcatEncPos.上探头Y --{encposUpy}"); Stopwatch stopwatch = new Stopwatch(); stopwatch.Start(); mc.GTN_GetEcatEncPos(nCore, 2, out encposUpy); if (stopwatch.ElapsedMilliseconds > 500) { Log.Info("GTN_GetEcatEncPos.上探头y超时报警------{stopwatch.ElapsedMilliseconds}"); MessageBox.Show("卡顿现象出现,测试停止."); runFlag = false; } Thread.Sleep(10); } MessageBox.Show("测试结束."); }); }

 这种问题还是挺有意思的，即 GTN_GetEcatEncPos 方法会有 10s 的卡慢情况，接下来我们就来探究下。 ## 二：为什么会卡慢
 ### 1. 使用 perfview
 像 GTN_GetEcatEncPos 这种动态性的卡死，首先看dump不是一个好的策略，最好的方式就是给程序安装摄像头，采集程序的运行状态，这里推荐的自然是 PerfView，开启 `墙钟模式` ，即定期的采集线程栈数据。 朋友按照建议拿到了 etl 文件，拿到 etl 文件之后，搜索 `TestRun` 方法，搜索内部匿名函数，截图如下： 从卦中看果然给捕获到了，那个所谓的 10s 卡满，原来是在 `gts（固高运动卡）` 下的 `kernelbase!WaitForSingleObject` 上，由于 gts 是闭源的，拿不到 pdb 符号所以显示不出内部函数，虽然没有直接找到祸根，但还是有一点进展的。 有些朋友可能会好奇，这个 perfview 到底追踪了多久，这个可以通过 TraceInfo 选项卡观察，截图如下： 从卦中可知，当前追踪了 65s。 ### 2. 路在何方
 只知道在 `kernelbase!WaitForSingleObject` 上等待了10s并不能解决问题，那怎么办呢？刚好朋友也给了我一份当时故障时的dump，这时候就要结合起来一起看，争取找到突破口。 首先通过 `~*e k` 寻找 TestRun 函数的调用栈，输出如下： ```
...
0:011:x86> k
 # ChildEBP RetAddr      
00 0a1ef350 76a024e9     ntdll_77760000!NtWaitForSingleObject+0xc
01 0a1ef350 76a02442     KERNELBASE!WaitForSingleObjectEx+0x99
02 0a1ef364 594a13d8     KERNELBASE!WaitForSingleObject+0x12
WARNING: Stack unwind information not available. Following frames may be wrong.
03 0a1ef388 721d284d     gts!PvSplit+0x3b8
04 0a1ef3c0 06ead2f8     clr!PInvokeStackImbalanceHelper+0x22
05 0a1ef404 06c74476     System_Windows_Forms!DomainBoundILStubClass.IL_STUB_PInvoke(Int16, Int16, Int32 ByRef)+0x78
06 0a1ef4a8 66bad0ab     xxx!xxx.xxx+<>c__DisplayClass136_0.<TestRun>b__0()+0x10e
07 0a1ef4b4 66baa0b1     mscorlib_ni!System.Threading.Tasks.Task.InnerInvoke()+0x4b
08 0a1ef4d8 66baa07c     mscorlib_ni!System.Threading.Tasks.Task.Execute()+0x31
09 0a1ef540 66b48e34     mscorlib_ni!System.Threading.Tasks.Task.ExecutionContextCallback(System.Object)+0x1c
0a 0a1ef540 66b48d67     mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0xc4
...
1e 0a1efb5c 777c806e     ntdll_77760000!__RtlUserThreadStart+0x2f
...

从卦中数据看果然是在 event 事件上等待，使用 kb 5 观察 event 参数，再使用 !handle 观察。 ``` 0:011:x86> kb 5

ChildEBP RetAddr Args to Child

00 0a1ef350 76a024e9 00000818 00000000 00000000 ntdll_77760000!NtWaitForSingleObject+0xc 01 0a1ef350 76a02442 00000818 ffffffff 00000000 KERNELBASE!WaitForSingleObjectEx+0x99 02 0a1ef364 594a13d8 00000818 ffffffff 0a1ef3ac KERNELBASE!WaitForSingleObject+0x12 WARNING: Stack unwind information not available. Following frames may be wrong. 03 0a1ef388 721d284d 00000001 00000002 0288a9c8 gts!PvSplit+0x3b8 04 0a1ef3c0 06ead2f8 00000001 00000002 0288a9c8 clr!PInvokeStackImbalanceHelper+0x22

0:011:x86> !handle 00000818f Handle 0000818f Type 0:011:x86> !handle 00000818 f Handle 00000818 Type Event Attributes 0 GrantedAccess 0x1f0003: Delete,ReadControl,WriteDac,WriteOwner,Synch QueryState,ModifyState HandleCount 3 PointerCount 65540 Name \BaseNamedObjects\MultiProcess Object specific information Event Type Auto Reset Event is Waiting

 从卦中可以看到当前是一个名为 `\BaseNamedObjects\MultiProcess` 的 AutoResetEvent 事件，正处于等待状态，验证了 perfview 的数据，那到底是在等待谁呢？ ### 3. 在绝望中寻找希望
 分析dump就是这样，一步一个坎。。。所以不抛弃不放弃，因为这个程序是一个窗体程序，朋友又提到了卡死的关键词，所以本能的想看看此时的主线程正在做什么，使用 `~0s ; k` 命令。 ```
0:000:x86> ~0s; k
 # ChildEBP RetAddr      
00 006fe638 76a024e9     ntdll_77760000!NtWaitForSingleObject+0xc
01 006fe638 76a02442     KERNELBASE!WaitForSingleObjectEx+0x99
02 006fe64c 75501328     KERNELBASE!WaitForSingleObject+0x12
WARNING: Stack unwind information not available. Following frames may be wrong.
03 006fe668 75544ac5     sysfer+0x1328
04 006fe878 755449c9     sysfer+0x44ac5
05 006fe910 755448ff     sysfer+0x449c9
06 006fe98c 75542ec6     sysfer+0x448ff
07 006fe9d0 777d324c     sysfer+0x42ec6
08 006fea30 76a1ac32     ntdll_77760000!NtSetInformationFile+0xc
09 006fea30 594a1bcc     KERNELBASE!SetFilePointer+0x72
0a 006fea54 594a1fff     gts!PvSplit+0xbac
0b 006fea68 5948164a     gts!PvSplit+0xfdf
0c 006fea88 59442e78     gts!GTN_SetHookSubModuleActive+0x70a
0d 006feaa4 721d284d     gts!GTN_GetDo+0x38
0e 006feadc 06ead2f8     clr!PInvokeStackImbalanceHelper+0x22
0f 006feb20 06ead89b     System_Windows_Forms!DomainBoundILStubClass.IL_STUB_PInvoke(Int16, Int16, Int32 ByRef)+0x78
10 006fec08 06eacfe6     xxx!xxx.xxx.CompareSts()+0x1eb
11 006fed6c 06eacb35     xxx!xxx.xxx.timerSts_Tick(System.Object, System.EventArgs)+0x49e
12 006fed80 06eac3ae     System_Windows_Forms!System.Windows.Forms.Timer.OnTick(System.EventArgs)+0x15
...

不看不知道，一看卦吓一跳，除了刚才已经熟悉的 gts!PvSplit ，还发现了一个未知的 sysfer.dll ，这是啥玩意，一下子就提起了兴趣，使用 lmvm sysfer 观察。 ``` 0:000:x86> lmvm sysfer Browse full module list start end module name 75500000 7557e000 sysfer (no symbols)
Loaded symbol image file: sysfer.dll Image path: C:\Windows\SysWOW64\sysfer.dll Image name: sysfer.dll Browse all global symbols functions data Symbol Reload Timestamp: Sat Apr 20 02:38:55 2019 (5CBA15BF) CheckSum: 0006E5AE ImageSize: 0007E000 File version: 14.2.3329.1000 Product version: 14.2.3329.1000 File flags: 0 (Mask 0) File OS: 40004 NT Win32 File type: 1.0 App File date: 00000000.00000000 Translations: 0409.04e4 Information from resource tables: CompanyName: Symantec Corporation ProductName: Symantec CMC Firewall InternalName: sysfer OriginalFilename: sysfer.dll ProductVersion: 14.2.3329.1000 FileVersion: 14.2.3329.1000 FileDescription: Symantec CMC Firewall sysfer LegalCopyright: Copyright (c) 2006-2019 Symantec Corporation. All rights reserved. Use of this product is subject to license terms.

 从 `Symantec CMC Firewall sysfer` 来看，应该是赛门铁克的一个 `客户端防火墙组件` ，再回头看调用栈，大概就是 gts 在内部设置文件偏移指针(SetFilePointer) 的时候被 `赛门铁克` 拦截了。 到这里基本上就弄清楚了卡死 10s 的来龙去脉，11号线程在 gts 中等待 0号线程 唤醒它的 event 事件。 而 0号线程不巧在设置文件指针的时候被 `赛门铁克` 拦截了，在这拦截的10s内，导致 0 号线程没有及时的唤醒 11 号线程所等待的事件，最终导致悲剧的发生。。。 ## 三：总结
 这次卡慢事故是由于 `赛门铁克` 导致，其实杀毒软件对我们程序来说真的是一个特别不稳定的因素，在我的分析旅程中，我见过杀毒软件导致的崩溃，卡死，卡慢，内存泄露 等等奇葩情况，无语了。。。

> 原文链接: https://www.cnblogs.com/huangxincheng/p/18824441