记一次 .NET 某游戏网站 CPU爆高分析

2023-02-13 00:00:00 线程请求方法这一朋友

一：背景

1. 讲故事

这段时间经常有朋友微信上问我这个真实案例分析连载怎么不往下续了，关注我的朋友应该知道，我近二个月在研究 SQLSERVER，也写了十多篇文章，为什么要研究这东西呢？是因为在 dump 中发现有不少的问题是 SQLSERVER 端产生的，比如：遗留事务，索引缺失 ，这让我产生了非常大的兴趣，毕竟他们是一对黄金搭档。

回到本话题上来，年前有位朋友找到我，说他的程序在业务高峰期的时候CPU一直居高不下，咨询一下是什么问题？按照老规矩，上 WinDbg 说话。

二：WinDbg 分析

1. CPU 真的爆高吗

拿到dump之后一定要用数据说话，有时候口头描述会给你带偏，这里用 !tp 验证一下。


:043> !tp
CPU utilization: 91%
Worker Thread: Total: 11 Running: 4 Idle:  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: 
--------------------------------------
Completion Port Thread:Total: 2 Free: 2 MaxFree: 8 CurrentLimit: 2 MaxLimit: 1000 MinLimit: 4

这一看吓一跳，在CPU符合预期之外，线程池队列居然累计了高达 1756 个任务未被及时处理，造成这种现象一般有两种情况，要么是线程卡死了，要么是负载过大，相对来说前者居多。

2. 线程都被卡住了吗？

有了这个思路之后，接下来可以用 ~*e !clrstack 观察下所有线程栈是不是有什么东西卡住他们了。


:043> ~*e !clrstack
OS Thread Id: 0x53c4 ()
...
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 命令探究下。


:043> !cpuid
CP  F/M/S  Manufacturer     MHz
   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 命令观察即可。


: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。
横向扩展，增加机器。
预计算，根据业务来

相关文章