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

news2024/9/21 2:42:40

一：背景

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] 请求，截图如下：