Windbg程序調試系列5-高CPU問題分析

時間 2019-11-05

標籤 windbg 程序調試系列 cpu 問題分析简体版

原文原文鏈接

上篇博客中給你們分享了使用Windbg進行Live Debugging：html

Windbg程序調試系列4-Live Debuggingc++

本篇中咱們繼續，跟你們分享常見的應用程序高CPU使用率問題分析。session

先說Windows下CPU使用率這個概念：架構

CPU使用率：在任務管理器的刷新週期內CPU忙的時間與整個刷新週期的比值。默認的刷新週期是1s。
ide

即1s內，反映出系統的CPU繁忙程度post

咱們打開Windows的任務管理器，能夠看到CPU的使用率:優化

固然，這個CPU使用率是整個全部核心CPU的使用率。好比我本機是8核心的CPU。總體的CPU使用率在某一瞬間是14%。ui

這個CPU使用率是如何計算出來的，有兩個重要的時間sysTime和idleTime:spa

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問題：

1、首先咱們用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。

2、查看應用進程的CPU使用率

從任務管理器上，可以發現，HighCpuDemo這個進程的CPU使用率是12%

3、間隔30s，抓兩個Dump

這裏有個問題：爲何要間隔一段時間抓2個dump？咱們先把問題放在這。

4、使用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 c3              ret
0:000> .loadby sos clr
0:000> !runaway
 User Mode Time
  Thread       Time
   4: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

第二個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              ret
0:000> .loadby sos clr
0:000> !runaway
 User Mode Time
  Thread       Time
   4: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

這裏有個關鍵的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       Time
 0:55c        0:00:00.0093
 1:1a4        0:00:00.0000

 Kernel Mode Time
 Thread       Time
 0: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

使用這個指令，能夠查看每一個線程的"用戶態"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 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.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]