记一次 .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+0x220:011:x86> !handle 00000818f
Handle 0000818fType         	<Error retrieving type>
0:011:x86> !handle 00000818 f
Handle 00000818Type         	EventAttributes   	0GrantedAccess	0x1f0003:Delete,ReadControl,WriteDac,WriteOwner,SynchQueryState,ModifyStateHandleCount  	3PointerCount 	65540Name         	\BaseNamedObjects\MultiProcessObject specific informationEvent Type Auto ResetEvent 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.dllImage path: C:\Windows\SysWOW64\sysfer.dllImage name: sysfer.dllBrowse all global symbols  functions  data  Symbol ReloadTimestamp:        Sat Apr 20 02:38:55 2019 (5CBA15BF)CheckSum:         0006E5AEImageSize:        0007E000File version:     14.2.3329.1000Product version:  14.2.3329.1000File flags:       0 (Mask 0)File OS:          40004 NT Win32File type:        1.0 AppFile date:        00000000.00000000Translations:     0409.04e4Information from resource tables:CompanyName:      Symantec CorporationProductName:      Symantec CMC FirewallInternalName:     sysferOriginalFilename: sysfer.dllProductVersion:   14.2.3329.1000FileVersion:      14.2.3329.1000FileDescription:  Symantec CMC Firewall sysferLegalCopyright:   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 号线程所等待的事件，最终导致悲剧的发生。。。