一:背景
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。
- 横向扩展,增加机器。
- 预计算,根据业务来
![图片名称](https://images.cnblogs.com/cnblogs_com/huangxincheng/345039/o_210929020104最新消息优惠促销公众号关注二维码.jpg)