記一次 .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號