Windbg程序調(diào)試系列5-高CPU問題分析

上篇博客中給大家分享了使用Windbg進(jìn)行Live Debugging：

Windbg程序調(diào)試系列4-Live Debugging <https://www.cnblogs.com/tianqing/p/9905738.html>

本篇中我們繼續(xù)，跟大家分享常見的應(yīng)用程序高CPU使用率問題分析。

先說Windows下CPU使用率這個(gè)概念：

CPU使用率：在任務(wù)管理器的刷新周期內(nèi)CPU忙的時(shí)間與整個(gè)刷新周期的比值。默認(rèn)的刷新周期是1s。


即1s內(nèi)，反映出系統(tǒng)的CPU繁忙程度

我們打開Windows的任務(wù)管理器，可以看到CPU的使用率:



當(dāng)然，這個(gè)CPU使用率是整個(gè)所有核心CPU的使用率。比如我本機(jī)是8核心的CPU。整體的CPU使用率 在某一瞬間是14%。

這個(gè)CPU使用率是如何計(jì)算出來的，有兩個(gè)重要的時(shí)間sysTime和idleTime:

sysTime：表示該時(shí)間段內(nèi)總的CPU時(shí)間=CPU處于用戶態(tài)和內(nèi)核態(tài)CPU時(shí)間的總和，即sysTime =kerneTimel + userTime

（注：這里并不包括idleTime，因?yàn)楫?dāng)CPU處于空閑狀態(tài)時(shí)，是在內(nèi)核模式下運(yùn)行System Idle
Process這個(gè)進(jìn)程，所以kernelTime實(shí)際上已經(jīng)包含了idleTime）；

idleTime：表示在該時(shí)間段內(nèi)CPU處于空閑狀態(tài)的時(shí)間；
CPU% = 1 – idleTime / sysTime * 100
?說到這里，我們分析一個(gè)應(yīng)用的高cpu問題，更多的是：分析用戶態(tài)的CPU耗時(shí)。即，我們應(yīng)用程序本身運(yùn)行時(shí)消耗的CPU時(shí)間片總和。

然后，進(jìn)入今天的正題，使用Windbg分析高CPU問題：

一、首先我們用C#寫一個(gè)Any CPU架構(gòu)的Console模擬程序
using?System; using?System.Collections.Generic; using?System.Linq;
using?System.Text; using?System.Threading; using?System.Threading.Tasks;
namespace?HighCpuDemo { ????class?Program ????{
????????static?void?Main(string[]?args) ????????{ ????????????var?normalThread?
=?new?Thread(NormalMethod); ????????????normalThread.Start(); ????????????var?
longRunningThread?=?new?Thread(LongRunningMethod);
????????????longRunningThread.Start(); ????????????Console.ReadKey(); ????????}
????????private?static?void?NormalMethod() ????????{ ????????????int?a?=?0;
????????????int?b?=?100000; ????????????var?list?=?new?List<int>();
????????????for?(int?i?=?0;?i?<?b;?i++) ????????????{ ????????????????a?+=?i;
????????????????list.Add(a); ????????????????var?max?=?list.Max();
????????????????var?min?=?list.Min(); ????????????????var?avg?=?list.Average();
????????????????Console.WriteLine(string.Format("Thread:{0},?writeline:{1}",?Thread.CurrentThread.ManagedThreadId,?a));
????????????????//休息一下 ????????????????Thread.Sleep(100); ????????????}
????????} ????????private?static?void?LongRunningMethod() ????????{
????????????for?(int?c?=?0;?c?<?100000;?c++) ????????????{
????????????????int?a?=?0; ????????????????int?b?=?100000;
????????????????var?list?=?new?List<int>();
????????????????for?(int?i?=?0;?i?<?b;?i++) ????????????????{
????????????????????a?+=?i; ????????????????????list.Add(a);
????????????????????var?max?=?list.Max();
????????????????????var?min?=?list.Min();
????????????????????var?avg?=?list.Average();
????????????????????Console.WriteLine(string.Format("Thread:{0},?writeline:{1}",?Thread.CurrentThread.ManagedThreadId,?a));
????????????????} ????????????} ????????} ????} }
代碼中有兩個(gè)線程，一個(gè)是“正常”的計(jì)算輸出線程N(yùn)ormalThread（每次輸出，會(huì)休息一下
100s），一個(gè)是長(zhǎng)時(shí)間運(yùn)行的線程LongRunningThread，一直在計(jì)算，輸出。

代碼寫好之后，設(shè)置為Any CPU架構(gòu)，支持64位模式：



看程序輸出：



很明顯，3號(hào)線程是NormalThread， 4號(hào)線程是LongRunningThread。

二、 查看應(yīng)用進(jìn)程的CPU使用率



從任務(wù)管理器上，能夠發(fā)現(xiàn)，HighCpuDemo這個(gè)進(jìn)程的CPU使用率是12%

三、間隔30s，抓兩個(gè)Dump



這里有個(gè)問題：為什么要間隔一段時(shí)間抓2個(gè)dump？我們先把問題放在這。

四、使用Windbg分析兩個(gè)Dump文件，使用!runaway找到最消耗CPU時(shí)間片的線程，然后優(yōu)化



Windbg打開這兩個(gè)Dump后，分別執(zhí)行以下命令：
0:000> .loadby sos clr 0:000> !runaway
對(duì)比看著兩個(gè)Dump的輸出：

第一個(gè)Dump：
Debug session time: Sun Nov 25 20:16:39.000 2018 (GMT+8) System Uptime: 0 days
3:03:00.195 Process Uptime: 0 days 0:08:31.000 .............................
Loading unloaded module list . ntdll!ZwDeviceIoControlFile+0x14:
00007ffc`c01b03a4 c3 ret0:000> .loadby sos clr 0:000> !runaway User Mode Time
Thread Time4:3758 0 days 0:07:38.531 3:325c 0 days 0:00:00.390 0:2248 0 days 0:
00:00.015 6:4c3c 0 days 0:00:00.000 5:17d0 0 days 0:00:00.000 2:278 0 days 0:00:
00.000 1:2424 0 days 0:00:00.000
第二個(gè)Dump：
Debug session time: Sun Nov 25 20:17:06.000 2018 (GMT+8) System Uptime: 0 days
3:03:27.136 Process Uptime: 0 days 0:08:58.000 .............................
Loading unloaded module list . ntdll!ZwDeviceIoControlFile+0x14:
00007ffc`c01b03a4 c3 ret0:000> .loadby sos clr 0:000> !runaway User Mode Time
Thread Time4:3758 0 days 0:08:01.984 3:325c 0 days 0:00:00.406 0:2248 0 days 0:
00:00.015 6:4c3c 0 days 0:00:00.000 5:17d0 0 days 0:00:00.000 2:278 0 days 0:00:
00.000 1:2424 0 days 0:00:00.000
這里有個(gè)關(guān)鍵的Windbg指令? !runaway， 它有什么作用，輸出的是什么：
This extension is a quick way to find out which threads are spinning out of
control or consuming too much CPU time. The display identifies each thread by
the debugger's internal thread numbering and by the thread ID in hexadecimal.
The debugger IDs are also shown. Here is an example: 0:001> !runaway 7 User
Mode Time Thread Time0:55c 0:00:00.0093 1:1a4 0:00:00.0000 Kernel Mode Time
Thread Time0:55c 0:00:00.0140 1:1a4 0:00:00.0000 Elapsed Time Thread Time 0:55c
0:00:43.0533 1:1a4 0:00:25.0876
使用這個(gè)指令，可以查看每個(gè)線程的"用戶態(tài)"CPU使用時(shí)間：

從上面兩個(gè)Dump中，我們能看出，4號(hào)線程 User Mode Time 一直在增加，我們看看4號(hào)線程的堆棧：
0:000> ~4s *** WARNING: Unable to verify checksum for System.Core.ni.dll
System_Core_ni+0x588b44: 00007ffc`a4268b44 488b4de8 mov rcx,qword ptr [rbp-18h]
ss:000000c1`df0ff2a8=000001d4633eb280 0:004> !clrstack OS Thread Id: 0x3758 (4)
Child SP IP Call Site 000000c1df0ff280 00007ffca4268b44
System.Linq.Enumerable.Min(System.Collections.Generic.IEnumerable`1<Int32>)
000000c1df0ff2d0 00007ffc4b930660*** WARNING: Unable to verify checksum for
HighCpuDemo.exeHighCpuDemo.Program.LongRunningMethod()
[c:\users\zhougq\documents\visual studio2015\Projects\HighCpuDemo\Program.cs @
54] 000000c1df0ff3a0 00007ffca7e24770
System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext,
System.Threading.ContextCallback, System.Object, Boolean)
[f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @954]
000000c1df0ff470 00007ffca7e24604
System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext,
System.Threading.ContextCallback, System.Object, Boolean)
[f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @902]
000000c1df0ff4a0 00007ffca7e245d2
System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext,
System.Threading.ContextCallback, System.Object)
[f:\dd\ndp\clr\src\BCL\system\threading\executioncontext.cs @891]
000000c1df0ff4f0 00007ffca7eacff2 System.Threading.ThreadHelper.ThreadStart()
[f:\dd\ndp\clr\src\BCL\system\threading\thread.cs @111] 000000c1df0ff748
00007ffcaaf35863 [GCFrame: 000000c1df0ff748] 000000c1df0ffa98 00007ffcaaf35863
[DebuggerU2MCatchHandlerFrame: 000000c1df0ffa98]
正如我們代碼中所寫的，LongRunningMethod方法一直在執(zhí)行、消耗CPU資源。

定位到代碼問題，就可以進(jìn)一步修改代碼，解決問題了。

以上就是使用Windbg 調(diào)試高CPU問題的方法思路，總結(jié)一下：

1. 查看應(yīng)用進(jìn)程的CPU使用率
2. 間隔一段時(shí)間，抓兩個(gè)Dump
3. 使用Windbg分析兩個(gè)Dump文件，使用!runaway找到最消耗CPU時(shí)間片的線程，然后優(yōu)化

?分享給大家。

?

周國(guó)慶

2018/11/25

• ? 上一篇：終極版Servlet——我只能提示您路過別錯(cuò)過
• ? 下一篇：神奇的 SQL 之子查詢，細(xì)節(jié)滿滿 ！