Windbg程式除錯系列5-高CPU問題分析
上篇部落格中給大家分享了使用Windbg進行Live Debugging：
ofollow,noindex" target="_blank">Windbg程式除錯系列4-Live Debugging
本篇中我們繼續，跟大家分享常見的應用程式高CPU使用率問題分析。
先說Windows下CPU使用率這個概念：
CPU使用率：在工作管理員的重新整理週期內CPU忙的時間與整個重新整理週期的比值。預設的重新整理週期是1s。
即1s內，反映出系統的CPU繁忙程度
我們開啟Windows的工作管理員，可以看到CPU的使用率:
當然，這個CPU使用率是整個所有核心CPU的使用率。比如我本機是8核心的CPU。整體的CPU使用率 在某一瞬間是14%。
這個CPU使用率是如何計算出來的，有兩個重要的時間sysTime和idleTime:
sysTime：表示該時間段內總的CPU時間=CPU處於使用者態和核心態CPU時間的總和，即sysTime =kerneTimel + userTime
（注：這裡並不包括idleTime，因為當CPU處於空閒狀態時，是在核心模式下執行System Idle Process這個程序，所以kernelTime實際上已經包含了idleTime）；
idleTime：表示在該時間段內CPU處於空閒狀態的時間；
CPU% = 1 – idleTime / sysTime * 100
說到這裡，我們分析一個應用的高cpu問題，更多的是： 分析使用者態的CPU耗時。即，我們應用程式本身執行時消耗的CPU時間片總和。
然後，進入今天的正題，使用Windbg分析高CPU問題：
一、首先我們用C#寫一個Any CPU架構的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));
}
}
}
}
}
程式碼中有兩個執行緒，一個是“ 正常 ”的計算輸出執行緒NormalThread（每次輸出，會休息一下 100s），一個是長時間執行的執行緒LongRunningThread，一直在計算，輸出。
程式碼寫好之後，設定為Any CPU架構，支援64位模式：
看程式輸出：
很明顯，3號執行緒是NormalThread， 4號執行緒是LongRunningThread。
二、 檢視應用程序的CPU使用率
從工作管理員上，能夠發現，HighCpuDemo這個程序的CPU使用率是12%
三、間隔30s，抓兩個Dump
這裡有個問題：為什麼要間隔一段時間抓2個dump？我們先把問題放在這。
四、使用Windbg分析兩個Dump檔案，使用!runaway找到最消耗CPU時間片的執行緒，然後優化
Windbg開啟這兩個Dump後，分別執行以下命令：
0:000> .loadby sos clr 0:000> !runaway
對比看著兩個Dump的輸出：
第一個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 c3ret 0:000> .loadby sos clr 0:000> !runaway User Mode Time ThreadTime 4:37580 days 0:07:38.531 3:325c0 days 0:00:00.390 0:22480 days 0:00:00.015 6:4c3c0 days 0:00:00.000 5:17d00 days 0:00:00.000 2:2780 days 0:00:00.000 1:24240 days 0:00:00.000
第二個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 c3ret 0:000> .loadby sos clr 0:000> !runaway User Mode Time ThreadTime 4:37580 days 0:08:01.984 3:325c0 days 0:00:00.406 0:22480 days 0:00:00.015 6:4c3c0 days 0:00:00.000 5:17d00 days 0:00:00.000 2:2780 days 0:00:00.000 1:24240 days 0:00:00.000
這裡有個關鍵的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 ThreadTime 0:55c0:00:00.0093 1:1a40:00:00.0000 Kernel Mode Time ThreadTime 0:55c0:00:00.0140 1:1a40:00:00.0000 Elapsed Time ThreadTime 0:55c0:00:43.0533 1:1a40:00:25.0876
使用這個指令，可以檢視每個執行緒的"使用者態"CPU使用時間：
從上面兩個Dump中，我們能看出，4號執行緒 User Mode Time 一直在增加，我們看看4號執行緒的堆疊：
0:000> ~4s *** WARNING: Unable to verify checksum for System.Core.ni.dll System_Core_ni+0x588b44: 00007ffc`a4268b44 488b4de8movrcx,qword ptr [rbp-18h] ss:000000c1`df0ff2a8=000001d4633eb280 0:004> !clrstack OS Thread Id: 0x3758 (4) Child SPIP Call Site 000000c1df0ff280 00007ffca4268b44 System.Linq.Enumerable.Min(System.Collections.Generic.IEnumerable`1<Int32>) 000000c1df0ff2d0 00007ffc4b930660 *** WARNING: Unable to verify checksum for HighCpuDemo.exe HighCpuDemo.Program.LongRunningMethod() [c:\users\zhougq\documents\visual studio 2015\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方法一直在執行、消耗CPU資源。
定位到程式碼問題，就可以進一步修改程式碼，解決問題了。
以上就是使用Windbg 除錯高CPU問題的方法思路，總結一下：
1. 檢視應用程序的CPU使用率
2. 間隔一段時間，抓兩個Dump
3. 使用Windbg分析兩個Dump檔案，使用!runaway找到最消耗CPU時間片的執行緒，然後優化
分享給大家。
周國慶
2018/11/25