分析 .NET 某遊戲網站 CPU爆高

一：背景

1. 講故事

這段時間經常有朋友微信上問我這個

真實案例分析連載

怎麼不往下續了，關注我的朋友應該知道，我近二個月在研究 SQLSERVER，也寫了十多篇文章，為什麼要研究這東西呢？是因為在 dump 中發現有不少的問題是 SQLSERVER 端産生的，比如：

遺留事務

，

索引缺失

，這讓我産生了非常大的興趣，畢竟他們是一對黃金搭檔。

回到本話題上來，年前有位朋友找到我，說他的程式在業務高峰期的時候CPU一直居高不下，咨詢一下是什麼問題？按照老規矩，上 WinDbg 說話。

二：WinDbg 分析

1. CPU 真的爆高嗎

拿到dump之後一定要用資料說話，有時候口頭描述會給你帶偏，這裡用

!tp

驗證一下。

0:043> !tp
CPU utilization: 91%
Worker Thread: Total: 11 Running: 4 Idle: 0 MaxLimit: 8191 MinLimit: 4
Work Request in Queue: 1756
 Unknown Function: 72179e93 Context: 2104b3a4
 Unknown Function: 72179e93 Context: 204230c8
 Unknown Function: 72179e93 Context: 210523dc
 Unknown Function: 72179e93 Context: 20f13224
 Unknown Function: 72179e93 Context: 204110ac
 Unknown Function: 72179e93 Context: 2042e0a4
 Unknown Function: 72179e93 Context: 204310bc
 Unknown Function: 72179e93 Context: 204320c4
 Unknown Function: 72179e93 Context: 2042f0b0
 ...
 Unknown Function: 72179e93 Context: 2110a364
 Unknown Function: 72179e93 Context: 20e882e8
 Unknown Function: 72179e93 Context: 20e91330
--------------------------------------
Number of Timers: 0
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 8 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 4

           

這一看吓一跳，在CPU符合預期之外，線程池隊列居然累計了高達

1756

個任務未被及時處理，造成這種現象一般有兩種情況，要麼是線程卡死了，要麼是負載過大，相對來說前者居多。

2. 線程都被卡住了嗎？

有了這個思路之後，接下來可以用

~*e !clrstack

觀察下所有線程棧是不是有什麼東西卡住他們了。

0:043> ~*e !clrstack
OS Thread Id: 0x53c4 (0)
...
OS Thread Id: 0x4124 (42)
Child SP IP Call Site
218acdd8 700facce System.Threading.Tasks.Task.set_CapturedContext(System.Threading.ExecutionContext) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Task.cs @ 1779]
218acde8 7094fe81 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]]..ctor(System.Func`1<System.__Canon>) [f:\dd\ndp\clr\src\BCL\system\threading\Tasks\Future.cs @ 142]
...
OS Thread Id: 0x5be8 (43)
Child SP IP Call Site
2192c820 7746c03c [InlinedCallFrame: 2192c820] 
2192c81c 6f47adbc DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
2192c820 6f417230 [InlinedCallFrame: 2192c820] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
...
OS Thread Id: 0x4b70 (47)
Child SP IP Call Site
1abedaec 7746c03c [InlinedCallFrame: 1abedaec] 
1abedae8 6f47adbc DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
1abedaec 6f417230 [InlinedCallFrame: 1abedaec] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
1abedb24 6f417230 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]
1abedb54 6f416fdf System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags) [f:\dd\NDP\fx\src\net\System\Net\Sockets\Socket.cs @ 1741]
1abedb78 6f415e64 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32) [f:\dd\NDP\fx\src\net\System\Net\Sockets\NetworkStream.cs @ 508]
1abedba8 701150ec System.IO.BufferedStream.ReadByte() [f:\dd\ndp\clr\src\BCL\system\io\bufferedstream.cs @ 814]
...

           

仔細觀察這些線程棧發現大多請求都在網絡IO上，并沒有什麼卡死的情況，是以這條路基本上就走不通了。

3. 是負載過大嗎？

如果要從這條路往下走該怎麼處理呢？首先看下 CPU 強不強，可以用

!cpuid

指令探究下。

0:043> !cpuid
CP F/M/S Manufacturer MHz
0 6,63,2 GenuineIntel 2394
1 6,63,2 GenuineIntel 2394
2 6,63,2 GenuineIntel 2394
3 6,63,2 GenuineIntel 2394

           

我去，堂堂一個Web伺服器就這點配置真的有點太省了，看樣子還真是請求過多線程處理不及，接下來的問題是怎麼看請求是否過多呢？可以到托管堆中去找

HttpContext

對象，因為它封裝了承接後的 web 請求，這裡使用

!whttp

指令觀察即可。

0:043> !whttp
Starting indexing at 10:24:39
1000000 objects...
2000000 objects...
Indexing finished at 10:24:42
423,973,906 Bytes in 2,535,718 Objects
Index took 00:00:02
HttpContext Thread Time Out Running Status Verb Url
02924904 -- 00:01:50 00:00:08 200 GET http://xxx?Ids=[xxx,xxx]
...
2793343c -- 00:01:50 Finished 200 GET http://xxx?Ids=[xxx,xxx]
27a67c30 -- 00:01:50 Finished 200 GET http://xxx?Ids=[xxx,xxx]
27a85568 -- 00:01:50 Finished 200 GET http://xxx?Ids=[xxx,xxx]
27aab224 -- 00:01:50 Finished 200 GET http://xxx?Ids=[xxx,xxx]
27b08de4 -- 00:01:50 Finished 200 GET http://xxx?Ids=[xxx,xxx]
27b4ab60 -- 00:01:50 00:00:08 200 GET http://xxx?Ids=[xxx,xxx]
...
3543e0bc 37 00:01:50 00:00:00 200 GET http://xxx?Ids=[xxx,xxx]

1,197 HttpContext object(s) found matching criteria

You may also be interested in
================================
Dump HttpRuntime info: !wruntime

           

這一看又吓一跳，托管堆上

1197

個 HttpContext，幾乎都是

http://xxx?Ids=[xxx,xxx]

請求，截圖如下：

我相信線程池隊列中排隊的

1756

個請求應該幾乎也是

http://xxx?Ids=[xxx,xxx]

，這一前一後加起來有 3000 左右的并發請求，哈哈，3000 大軍把 CPU 按在地上摩擦。

4. 尋找問題方法

有了請求之後就可以尋找對應的處理方法，為了保密這裡就不細說了，方法有很多的邏輯，對外還涉及到了 Redis，ES 等第三方元件，看樣子這方法并發度并不高，也難怪并發高了CPU處理不及。

接下來就是建議朋友優化這個方法，能緩存的就緩存，根據朋友回報整體改動後效果不好，采用了其他的預生成措施解決了這個問題，觀察後 CPU 也正常了。

三：總結

這個 dump 還是蠻有意思的，真的是屬于請求過載導緻的 CPU 爆高，解決辦法也有很多：

• 縱向擴充，增加 CPU。
• 橫向擴充，增加機器。
• 預計算，根據業務來

END

工作中的你，是否已遇到 ...

1. CPU爆高

2. 記憶體暴漲

3. 資源洩漏

4. 崩潰死鎖

5. 程式呆滞

等緊急事件，全公司都指望着你能解決... 危難時刻才能展現你的技術價值，作為專注于.NET進階調試的技術部落客，歡迎微信搜尋: 一線碼農聊技術，免費協助你分析Dump檔案，希望我能将你的踩坑經驗分享給更多的人。