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

一：背景

1. 讲故事

年前有位朋友找到我，说他们的程序会偶发性卡慢 10s 钟，在某些组合下会正常，某些组合下就会出现问题，表明不了此中的缘故原由，让我资助看下怎么回事？截图如下：

1. private void TestRun()
2. {
3.         int encposUpy = 0;
4.         Logger Log = new Logger();
5.         Task.Factory.StartNew(delegate
6.         {
7.                 Log.Info("GTN_GetEcatEncPos.上探头Y------start。");
8.                 while (runFlag)
9.                 {
10.                         Log.Info($"GTN_GetEcatEncPos.上探头Y --{encposUpy}");
11.                         Stopwatch stopwatch = new Stopwatch();
12.                         stopwatch.Start();
13.                         mc.GTN_GetEcatEncPos(nCore, 2, out encposUpy);
14.                         if (stopwatch.ElapsedMilliseconds > 500)
15.                         {
16.                                 Log.Info($"GTN_GetEcatEncPos.上探头y超时报警------{stopwatch.ElapsedMilliseconds}");
17.                                 MessageBox.Show("卡顿现象出现,测试停止.");
18.                                 runFlag = false;
19.                         }
20.                         Thread.Sleep(10);
21.                 }
22.                 MessageBox.Show("测试结束.");
23.         });
24. }

复制代码

这种问题还是挺有意思的，即 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 函数的调用栈，输出如下：

1. ...
2. 0:011:x86> k
3. # ChildEBP RetAddr      
4. 00 0a1ef350 76a024e9     ntdll_77760000!NtWaitForSingleObject+0xc
5. 01 0a1ef350 76a02442     KERNELBASE!WaitForSingleObjectEx+0x99
6. 02 0a1ef364 594a13d8     KERNELBASE!WaitForSingleObject+0x12
7. WARNING: Stack unwind information not available. Following frames may be wrong.
8. 03 0a1ef388 721d284d     gts!PvSplit+0x3b8
9. 04 0a1ef3c0 06ead2f8     clr!PInvokeStackImbalanceHelper+0x22
10. 05 0a1ef404 06c74476     System_Windows_Forms!DomainBoundILStubClass.IL_STUB_PInvoke(Int16, Int16, Int32 ByRef)+0x78
11. 06 0a1ef4a8 66bad0ab     xxx!xxx.xxx+<>c__DisplayClass136_0.<TestRun>b__0()+0x10e
12. 07 0a1ef4b4 66baa0b1     mscorlib_ni!System.Threading.Tasks.Task.InnerInvoke()+0x4b
13. 08 0a1ef4d8 66baa07c     mscorlib_ni!System.Threading.Tasks.Task.Execute()+0x31
14. 09 0a1ef540 66b48e34     mscorlib_ni!System.Threading.Tasks.Task.ExecutionContextCallback(System.Object)+0x1c
15. 0a 0a1ef540 66b48d67     mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)+0xc4
16. ...
17. 1e 0a1efb5c 777c806e     ntdll_77760000!__RtlUserThreadStart+0x2f
18. ...

复制代码

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

1. 0:011:x86> kb 5
2. # ChildEBP RetAddr      Args to Child              
3. 00 0a1ef350 76a024e9     00000818 00000000 00000000 ntdll_77760000!NtWaitForSingleObject+0xc
4. 01 0a1ef350 76a02442     00000818 ffffffff 00000000 KERNELBASE!WaitForSingleObjectEx+0x99
5. 02 0a1ef364 594a13d8     00000818 ffffffff 0a1ef3ac KERNELBASE!WaitForSingleObject+0x12
6. WARNING: Stack unwind information not available. Following frames may be wrong.
7. 03 0a1ef388 721d284d     00000001 00000002 0288a9c8 gts!PvSplit+0x3b8
8. 04 0a1ef3c0 06ead2f8     00000001 00000002 0288a9c8 clr!PInvokeStackImbalanceHelper+0x22
10. 0:011:x86> !handle 00000818f
11. Handle 0000818f
12.   Type                 <Error retrieving type>
13. 0:011:x86> !handle 00000818 f
14. Handle 00000818
15.   Type                 Event
16.   Attributes           0
17.   GrantedAccess        0x1f0003:
18.          Delete,ReadControl,WriteDac,WriteOwner,Synch
19.          QueryState,ModifyState
20.   HandleCount          3
21.   PointerCount         65540
22.   Name                 \BaseNamedObjects\MultiProcess
23.   Object specific information
24.     Event Type Auto Reset
25.     Event is Waiting

复制代码

从卦中可以看到当前是一个名为 \BaseNamedObjects\MultiProcess 的 AutoResetEvent 事件，正处于等待状态，验证了 perfview 的数据，那到底是在等待谁呢？
3. 在绝望中探求希望

分析dump就是这样，一步一个坎。。。所以不抛弃不放弃，由于这个程序是一个窗体程序，朋友又提到了卡死的关键词，所以本能的想看看此时的主线程正在做什么，使用 ~0s ; k 下令。

1. 0:000:x86> ~0s; k
2. # ChildEBP RetAddr      
3. 00 006fe638 76a024e9     ntdll_77760000!NtWaitForSingleObject+0xc
4. 01 006fe638 76a02442     KERNELBASE!WaitForSingleObjectEx+0x99
5. 02 006fe64c 75501328     KERNELBASE!WaitForSingleObject+0x12
6. WARNING: Stack unwind information not available. Following frames may be wrong.
7. 03 006fe668 75544ac5     sysfer+0x1328
8. 04 006fe878 755449c9     sysfer+0x44ac5
9. 05 006fe910 755448ff     sysfer+0x449c9
10. 06 006fe98c 75542ec6     sysfer+0x448ff
11. 07 006fe9d0 777d324c     sysfer+0x42ec6
12. 08 006fea30 76a1ac32     ntdll_77760000!NtSetInformationFile+0xc
13. 09 006fea30 594a1bcc     KERNELBASE!SetFilePointer+0x72
14. 0a 006fea54 594a1fff     gts!PvSplit+0xbac
15. 0b 006fea68 5948164a     gts!PvSplit+0xfdf
16. 0c 006fea88 59442e78     gts!GTN_SetHookSubModuleActive+0x70a
17. 0d 006feaa4 721d284d     gts!GTN_GetDo+0x38
18. 0e 006feadc 06ead2f8     clr!PInvokeStackImbalanceHelper+0x22
19. 0f 006feb20 06ead89b     System_Windows_Forms!DomainBoundILStubClass.IL_STUB_PInvoke(Int16, Int16, Int32 ByRef)+0x78
20. 10 006fec08 06eacfe6     xxx!xxx.xxx.CompareSts()+0x1eb
21. 11 006fed6c 06eacb35     xxx!xxx.xxx.timerSts_Tick(System.Object, System.EventArgs)+0x49e
22. 12 006fed80 06eac3ae     System_Windows_Forms!System.Windows.Forms.Timer.OnTick(System.EventArgs)+0x15
23. ...

复制代码

不看不知道，一看卦吓一跳，除了刚才已经熟悉的 gts!PvSplit ，还发现了一个未知的 sysfer.dll ，这是啥玩意，一下子就提起了爱好，使用 lmvm sysfer 观察。

1. 0:000:x86> lmvm sysfer
2. Browse full module list
3. start    end        module name
4. 75500000 7557e000   sysfer     (no symbols)           
5.     Loaded symbol image file: sysfer.dll
6.     Image path: C:\Windows\SysWOW64\sysfer.dll
7.     Image name: sysfer.dll
8.     Browse all global symbols  functions  data  Symbol Reload
9.     Timestamp:        Sat Apr 20 02:38:55 2019 (5CBA15BF)
10.     CheckSum:         0006E5AE
11.     ImageSize:        0007E000
12.     File version:     14.2.3329.1000
13.     Product version:  14.2.3329.1000
14.     File flags:       0 (Mask 0)
15.     File OS:          40004 NT Win32
16.     File type:        1.0 App
17.     File date:        00000000.00000000
18.     Translations:     0409.04e4
19.     Information from resource tables:
20.         CompanyName:      Symantec Corporation
21.         ProductName:      Symantec CMC Firewall
22.         InternalName:     sysfer
23.         OriginalFilename: sysfer.dll
24.         ProductVersion:   14.2.3329.1000
25.         FileVersion:      14.2.3329.1000
26.         FileDescription:  Symantec CMC Firewall sysfer
27.         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 号线程所等待的事件，终极导致悲剧的发生。。。
三：总结

这次卡慢事故是由于 赛门铁克 导致，其实杀毒软件对我们程序来说真的是一个特殊不稳定的因素，在我的分析路程中，我见过杀毒软件导致的崩溃，卡死，卡慢，内存泄露 等等奇葩环境，无语了。。。

免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！更多信息从访问主页：qidao123.com:ToB企服之家，中国第一个企服评测及商务社交产业平台。

继续阅读请点击广告