記一次 .NET某固高運動卡測試卡慢分析

一：背景

1. 講故事

年前有位朋友找到我，說他們的程序會偶發(fā)性卡慢 10s 鐘，在某些組合下會正常，某些組合下就會出現問題，解釋不了其中的原因，讓我?guī)兔聪略趺椿厥拢拷貓D如下：


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 這種動態(tài)性的卡死，首先看dump不是一個好的策略，最好的方式就是給程序安裝攝像頭，采集程序的運行狀態(tài)，這里推薦的自然是 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 事件，正處于等待狀態(tài)，驗證了 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 ，還發(fā)現了一個未知的 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 號線程所等待的事件，最終導致悲劇的發(fā)生。。。

三：總結

這次卡慢事故是由于 賽門鐵克 導致，其實殺毒軟件對我們程序來說真的是一個特別不穩(wěn)定的因素，在我的分析旅程中，我見過殺毒軟件導致的崩潰，卡死，卡慢，內存泄露等等奇葩情況，無語了。。。
圖片名稱

posted @ 2025-04-14 11:33 一線碼農閱讀(1664) 評論(7) 收藏舉報

刷新頁面返回頂部

記一次 .NET某固高運動卡測試 卡慢分析