记一次 .NET某固高运动卡测试 卡慢分析
<h2 id="一背景">一：背景</h2><h3 id="1-讲故事">1. 讲故事</h3>
<p>年前有位朋友找到我，说他们的程序会偶发性卡慢 10s 钟，在某些组合下会正常，某些组合下就会出现问题，解释不了其中的原因，让我帮忙看下怎么回事？截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202504/214741-20250414113314351-705118983.png" alt="" loading="lazy"></p>
<pre><code class="language-C#">
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("测试结束.");
});
}
</code></pre>
<p>这种问题还是挺有意思的，即 GTN_GetEcatEncPos 方法会有 10s 的卡慢情况，接下来我们就来探究下。</p>
<h2 id="二为什么会卡慢">二：为什么会卡慢</h2>
<h3 id="1-使用-perfview">1. 使用 perfview</h3>
<p>像 GTN_GetEcatEncPos 这种动态性的卡死，首先看dump不是一个好的策略，最好的方式就是给程序安装摄像头，采集程序的运行状态，这里推荐的自然是 PerfView，开启<code>墙钟模式</code>，即定期的采集线程栈数据。</p>
<p>朋友按照建议拿到了 etl 文件，拿到 etl 文件之后，搜索 <code>TestRun</code> 方法，搜索内部匿名函数，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202504/214741-20250414113314366-1291682950.png" alt="" loading="lazy"></p>
<p>从卦中看果然给捕获到了，那个所谓的 10s 卡满，原来是在 <code>gts（固高运动卡）</code> 下的 <code>kernelbase!WaitForSingleObject</code> 上，由于 gts 是闭源的，拿不到 pdb 符号所以显示不出内部函数，虽然没有直接找到祸根，但还是有一点进展的。</p>
<p>有些朋友可能会好奇，这个 perfview 到底追踪了多久，这个可以通过 TraceInfo 选项卡观察，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202504/214741-20250414113314384-708232100.png" alt="" loading="lazy"></p>
<p>从卦中可知，当前追踪了 65s。</p>
<h3 id="2-路在何方">2. 路在何方</h3>
<p>只知道在 <code>kernelbase!WaitForSingleObject</code> 上等待了10s并不能解决问题，那怎么办呢？刚好朋友也给了我一份当时故障时的dump，这时候就要结合起来一起看，争取找到突破口。</p>
<p>首先通过 <code>~*e k</code> 寻找 TestRun 函数的调用栈，输出如下：</p>
<pre><code class="language-C#">...
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
...
</code></pre>
<p>从卦中数据看果然是在 event 事件上等待，使用 <code>kb 5</code> 观察 event 参数，再使用 <code>!handle</code> 观察。</p>
<pre><code class="language-C#">
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
</code></pre>
<p>从卦中可以看到当前是一个名为 <code>\BaseNamedObjects\MultiProcess</code> 的 AutoResetEvent 事件，正处于等待状态，验证了 perfview 的数据，那到底是在等待谁呢？</p>
<h3 id="3-在绝望中寻找希望">3. 在绝望中寻找希望</h3>
<p>分析dump就是这样，一步一个坎。。。所以不抛弃不放弃，因为这个程序是一个窗体程序，朋友又提到了卡死的关键词，所以本能的想看看此时的主线程正在做什么，使用 <code>~0s ; k</code> 命令。</p>
<pre><code class="language-C#">
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
...
</code></pre>
<p>不看不知道，一看卦吓一跳，除了刚才已经熟悉的 <code>gts!PvSplit</code> ，还发现了一个未知的 sysfer.dll ，这是啥玩意，一下子就提起了兴趣，使用 <code>lmvm sysfer</code> 观察。</p>
<pre><code class="language-C#">
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 symbolsfunctionsdataSymbol 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.
</code></pre>
<p>从 <code>Symantec CMC Firewall sysfer</code> 来看，应该是赛门铁克的一个 <code>客户端防火墙组件</code>，再回头看调用栈，大概就是 gts 在内部设置文件偏移指针(SetFilePointer) 的时候被 <code>赛门铁克</code> 拦截了。</p>
<p>到这里基本上就弄清楚了卡死 10s 的来龙去脉，11号线程在 gts 中等待 0号线程 唤醒它的 event 事件。 而 0号线程不巧在设置文件指针的时候被 <code>赛门铁克</code> 拦截了，在这拦截的10s内，导致 0 号线程没有及时的唤醒 11 号线程所等待的事件，最终导致悲剧的发生。。。</p>
<h2 id="三总结">三：总结</h2>
<p>这次卡慢事故是由于 <code>赛门铁克</code> 导致，其实杀毒软件对我们程序来说真的是一个特别不稳定的因素，在我的分析旅程中，我见过杀毒软件导致的崩溃，卡死，卡慢，内存泄露 等等奇葩情况，无语了。。。<br>
<img src="https://images.cnblogs.com/cnblogs_com/huangxincheng/345039/o_210929020104最新消息优惠促销公众号关注二维码.jpg" width="700" height="300" alt="图片名称" align="center"></p><br><br>
来源：https://www.cnblogs.com/huangxincheng/p/18824441
頁:
[1]