记一次 .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 <Error retrieving 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 号线程所等待的事件，最终导致悲剧的发生。。。
三：总结
这次卡慢事故是由于 赛门铁克 导致，其实杀毒软件对我们程序来说真的是一个特别不稳定的因素，在我的分析旅程中，我见过杀毒软件导致的崩溃，卡死，卡慢，内存泄露 等等奇葩情况，无语了。。。
浙公网安备 33010602011771号