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

一線碼農發表於2023-02-13
遊戲網站

一：背景

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。
  • 橫向擴充套件，增加機器。
  • 預計算，根據業務來
圖片名稱

相關文章