記一次 .NET 某人力資源網 CPU爆高分析
一:背景
1. 講故事
前段時間微信里有一位非訓練營學員找到我,說他們的系統在某些時段會cpu爆高,并伴有網絡帶寬的激增,不知道是什么情況,讓我幫忙看下怎么回事,哈哈,說這個故障之前,我先吐槽一下,地獄不空,在社區里我一個人的力量太微弱了,這5年來我給行業內開發朋友都是全免費分析,這也讓自己不堪重負,不得不考慮收縮,目前非學員首單免費,也只有我的訓練營學員才會永久免費分析。給自己的學員分析dump還是比較輕松的,畢竟大家都是有一定的調試體系知識,同根同源。
吐槽完畢,開始本篇的dump分析之旅。
二:CPU爆高分析
1. 為什么會cpu爆高
關于cpu爆高的dump,最好用procdump自動去抓,因為在我的分析之旅中,有不少人手工去抓cpu爆高往往都不大準,還有一點一定要相信數據而不是人言,使用 !tp 觀察cpu的利用率。
0:000> !tp
CPU utilization: 100%
Worker Thread: Total: 20 Running: 5 Idle: 7 MaxLimit: 32767 MinLimit: 12
Work Request in Queue: 0
--------------------------------------
Number of Timers: 2
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 24 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 12
從卦中看確實cpu被打爆,恰好昨天分析了一個 .net2.0 的dump,可氣的是沒有 !tp 命令,這就非??简炍覀兊腸lr知識了,需要知道 CPU utilization 這個值 sos 是從哪里取得的?如果你看過sscli源代碼,應該知道它是 win32threadpool.cpp 的一個全局變量。
SVAL_IMPL(long,ThreadpoolMgr,cpuUtilization);
接下來用 windbg 驗證下。
0:000> x clr!ThreadpoolMgr::cpuUtilization
00007ffb`08541558 clr!ThreadpoolMgr::cpuUtilization = <no type information>
0:000> dp clr!ThreadpoolMgr::cpuUtilization L1
00007ffb`08541558 00000000`00000064
0:000> ? 0x64
Evaluate expression: 100 = 00000000`00000064
從卦中看完全對上了,所以dump分析多了,不能對 sos 有太多的依賴。
接下來我們看下cpu的能力,因為自我分析過2core cpu程序之后,我對cpu的健壯性一直都非常好奇,有時候cpu爆高不是業務問題,是 cpu 真的太弱了,接下來使用 !cpuid 觀察便知。
0:000> !cpuid
CP F/M/S Manufacturer MHz
0 6,85,7 <unavailable> 2500
1 6,85,7 <unavailable> 2500
2 6,85,7 <unavailable> 2500
3 6,85,7 <unavailable> 2500
4 6,85,7 <unavailable> 2500
5 6,85,7 <unavailable> 2500
6 6,85,7 <unavailable> 2500
7 6,85,7 <unavailable> 2500
8 6,85,7 <unavailable> 2500
9 6,85,7 <unavailable> 2500
10 6,85,7 <unavailable> 2500
11 6,85,7 <unavailable> 2500
從卦中看當前是一個 8core 的cpu,能力方面還算說的過去,接下來使用 ~*e !clrstack 觀察下每個線程都在做什么?
0:000> ~*e !clrstack
OS Thread Id: 0x77fc (0)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process
Failed to start stack walk: 80070057
...
OS Thread Id: 0x74c4 (58)
Child SP IP Call Site
0000002f9c85e4c8 00007ffb14ea058a [HelperMethodFrame_1OBJ: 0000002f9c85e4c8] System.Threading.Thread.JoinInternal(Int32)
0000002f9c85e5d0 00007ffb06def9fe System.Threading.Thread.Join(System.TimeSpan) [f:\dd\ndp\clr\src\BCL\system\threading\thread.cs @ 701]
0000002f9c85e610 00007ffaaaa62f42 FreeRedis.Internal.IdleBus`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].ThreadJoin(System.TimeSpan)
0000002f9c85e6d0 00007ffaaaa62422 FreeRedis.Internal.IdleBus`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].ThreadScanWatchHandler()
...
OS Thread Id: 0x6618 (63)
Child SP IP Call Site
0000002f9bffcff8 00007ffb14ea001a [InlinedCallFrame: 0000002f9bffcff8] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
0000002f9bffcff8 00007ffb057310b2 [InlinedCallFrame: 0000002f9bffcff8] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
0000002f9bffcfd0 00007ffb057310b2 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
0000002f9bffd080 00007ffb056ae48f System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef) [f:\dd\NDP\fx\src\net\System\Net\Sockets\Socket.cs @ 1780]
0000002f9bffd100 00007ffb056ac845 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32) [f:\dd\NDP\fx\src\net\System\Net\Sockets\NetworkStream.cs @ 513]
0000002f9bffd170 00007ffb056ac6b1 System.Net.PooledStream.Read(Byte[], Int32, Int32) [f:\dd\NDP\fx\src\net\System\Net\_PooledStream.cs @ 469]
0000002f9bffd1d0 00007ffb056ad4a1 System.Net.Connection.SyncRead(System.Net.HttpWebRequest, Boolean, Boolean) [f:\dd\NDP\fx\src\net\System\Net\_Connection.cs @ 3346]
0000002f9bffd230 00007ffb056d07bb System.Net.ConnectStream.ProcessWriteCallDone(System.Net.ConnectionReturnResult) [f:\dd\NDP\fx\src\net\System\Net\_ConnectStream.cs @ 450]
0000002f9bffd270 00007ffb056c4ea9 System.Net.HttpWebRequest.CheckDeferredCallDone(System.Net.ConnectStream) [f:\dd\NDP\fx\src\net\System\Net\HttpWebRequest.cs @ 2109]
...
從卦象中看,只有幾個線程有調用棧,并且大多都掛在 event 事件上,這些并不能導致 cpu 爆高,這就讓人很迷茫了,難道這個也是手工抓取的不準嗎?
2. 走出迷霧
在思考了若干秒之后,馬上就意識到既然托管層沒問題,或許非托管有問題呢?畢竟 ~*e !clrstack 是一個肌肉記憶命令,接下來使用 ~* k 觀察各個非托管棧,果然發現有多處 ipFilter 外來模塊,截圖如下:

從卦中看 ipFilter 貌似是一個 ip過濾器,正在忙碌的處理,看樣子正在高頻計算導致的cpu臨時性爆高,那 ipFilter 是何方神圣呢?使用 lmvm ipFilter 觀察一下便知。
0:079> lmvm ipFilter
Browse full module list
start end module name
00007ffb`041c0000 00007ffb`041f0000 ipFilter (export symbols) ipFilter.dll
Loaded symbol image file: ipFilter.dll
Image path: D:\軟件\安全軟件\YunSuoAgent\x64\ipFilter.dll
Image name: ipFilter.dll
Browse all global symbols functions data
Timestamp: Wed Feb 5 19:14:48 2020 (5E3AA3A8)
CheckSum: 000367C5
ImageSize: 00030000
Translations: 0000.04b0 0000.04e4 0409.04b0 0409.04e4
Information from resource tables:
接下來拿 YunSuoAgent 到 bing上搜一下,原來是 云鎖 這款安全軟件,截圖如下:

3. 云鎖為什么會攔截
云鎖為什么會攔截,這個真搞不清楚,只能簡單猜測下,拿其中的 79號線程 具體來說,使用 k 和 !dso 命令。
0:079> k
# Child-SP RetAddr Call Site
00 0000002f`915ed080 00007ffb`041c89a7 ipFilter+0x12bd
01 0000002f`915ed0b0 00007ffb`041c81ab ipFilter+0x89a7
02 0000002f`915ed130 00007ffb`041c87e9 ipFilter+0x81ab
03 0000002f`915ed350 00007ffb`041c3298 ipFilter+0x87e9
04 0000002f`915ed440 00007ffb`041c9050 ipFilter+0x3298
05 0000002f`915ed5b0 00007ffb`041c920d ipFilter+0x9050
06 0000002f`915ed670 00007ffb`043201de ipFilter+0x920d
07 0000002f`915ed6c0 00007ffb`04320219 FilterKernel+0x501de
08 0000002f`915ed730 00007ffb`04320219 FilterKernel+0x50219
09 0000002f`915ed7a0 00007ffb`04330c92 FilterKernel+0x50219
0a 0000002f`915ed810 00007ffb`044f4524 FilterKernel+0x60c92
0b 0000002f`915ed850 00007ffb`045a297f agent_iis7_module!RegisterModule+0x1594
...
0:079> !dso
OS Thread Id: 0x74e4 (79)
RSP/REG Object Name
0000002F915ED9B8 0000002e062ccb60 System.Web.HttpContext
0000002F915ED9C0 0000002e062cc800 System.Web.Hosting.IIS7WorkerRequest
0000002F915EDEE8 0000002e062d0558 System.String /WebResource.axd
0000002F915EDF00 0000002d058ed588 ASP.global_asax
0000002F915EDF08 0000002d058ed588 ASP.global_asax
0000002F915EDF20 0000002e062d0558 System.String /WebResource.axd
0000002F915EDF40 0000002e062d0558 System.String /WebResource.axd
...
從卦中可以看到 ipFilter.dll 是注冊到 iis 的一個 httpmodule,同時也看到了一個比較特殊的 /WebResource.axd 文件,熟悉 asp.net 的朋友應該知道,它其實是一個 httphandler,專用來動態產生 css,js 資源的,不需要將 css,js 放到物理文件中,在網上也有很多關于 /WebResource.axd 的漏洞注入案例,所以這東西是 ipfilter 的重點監控之處,不過直接導致 cpu 爆高,這就有點讓人無語了。
將結果告訴朋友之后,讓朋友將 云鎖 關掉,CPU 終于下去了。
三:總結
今年遇到了好幾起 安全軟件 導致的各種問題,內存泄露,程序卡死,程序崩潰,以及本篇的 CPU 爆高,也是無語了。。。

浙公網安備 33010602011771號