Basic Windbg - 3.High CPU的分析及诊断方法

看代码先：

Code
 1using System;
 2using System.Threading;
 3
 4namespace HighCPU
 5{
 6    class Program
 7    {
 8        static void Main(string[] args)
 9        {
10            Console.Clear();
11            Console.WriteLine("到命令行下，切换到windbg目录，执行adplus -hang -pn highcpu.exe -o c:\\dumps");
12            Console.WriteLine("如果要停止，按Ctrl+C结束程序");
13            Console.WriteLine("====================================================");
14            
15            while (true)
16            {
17                Console.SetCursorPosition(0, 3);
18                Console.Write(DateTime.Now.Ticks.ToString());
19            }
20        }
21    }
22}
23

这部分要介绍的内容是，我们在生产环境下，发现aspnet_wp.exe或者w3wp.exe的CPU在“某段时间”内居高不下，或者你自己的某个windows service，“某段时间”内占用CPU居高不下。这里我们简称为High CPU。
对于High CPU，相对而言很简单。抓dump就好了，执行adplus -hang -pn highcpu.exe -o c:\dumps。对于实际生产环境，一般的，你要这么做：adplus -hang -pn w3wp.exe -o c:\dumps

抓到了dump，先不要急，等2-3分钟，再抓一次（假设这个时候你进程的CPU还是很高），等2-3分钟，再抓一次。一般，我们抓到三个就够本了。
打开windbg，按照顺序，分别打开这三个dump文件。
加载sos：.load clr20\sos.dll
然后敲一个新命令：!runaway，第一个dump的结果如下
0:000> !runaway
 User Mode Time
  Thread       Time
   0:12a8      0 days 0:00:00.967
   2:148c      0 days 0:00:00.000
   1:1528      0 days 0:00:00.000

看不出来什么，继续看第二个的
0:000> !runaway
 User Mode Time
  Thread       Time
   0:12a8      0 days 0:00:05.678
   2:148c      0 days 0:00:00.000
   1:1528      0 days 0:00:00.000

有点意思了，继续看第三个的
0:000> !runaway
 User Mode Time
  Thread       Time
   0:12a8      0 days 0:00:10.795
   2:148c      0 days 0:00:00.000
   1:1528      0 days 0:00:00.000

看到这里，基本差不多了，我们发现，thread 0执行的时间持续在增长，从最初的0秒到现在的10秒。从目前的情况看，high cpu基本上是thread 0的代码造成的。那么，我们用前面介绍的命令!clrstack看一下：
0:000> !clrstack
OS Thread Id: 0x12a8 (0)
ESP       EIP    
0026edb8 774e0f34 [NDirectMethodFrameStandaloneCleanup: 0026edb8] System.IO.__ConsoleStream.WriteFile(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte*, Int32, Int32 ByRef, IntPtr)
0026edd4 7936b388 System.IO.__ConsoleStream.WriteFileNative(Microsoft.Win32.SafeHandles.SafeFileHandle, Byte[], Int32, Int32, Int32, Int32 ByRef)
0026ee00 7936b2f4 System.IO.__ConsoleStream.Write(Byte[], Int32, Int32)
0026ee20 7936ab1c System.IO.StreamWriter.Flush(Boolean, Boolean)
0026ee38 793a7d8c System.IO.StreamWriter.Write(System.String)
0026ee50 79499046 System.IO.TextWriter+SyncTextWriter.Write(System.String)
0026ee5c 793ea4f6 System.Console.Write(System.String)
0026ee68 003e010f HighCPU.Program.Main(System.String[])
0026f0a8 79e7c74b [GCFrame: 0026f0a8]

这是第一个dump的，从中我们能看到，是在调用Console.Write
接着看第二个dump的，类似，我们发现如下代码：
0026ee5c 793ea4f6 System.Console.Write(System.String)
0026ee68 003e010f HighCPU.Program.Main(System.String[])

再看第三个dump，嗯，这个有点特殊。
0:000> !clrstack
OS Thread Id: 0x12a8 (0)
ESP       EIP    
0026ee20 774e0f34 [NDirectMethodFrameSlim: 0026ee20] Microsoft.Win32.Win32Native.SetConsoleCursorPosition(IntPtr, COORD)
0026ee34 793e8acb System.Console.SetCursorPosition(Int32, Int32)
0026ee68 003e00d5 HighCPU.Program.Main(System.String[])
0026f0a8 79e7c74b [GCFrame: 0026f0a8]

那么，此时我们可以通过后面介绍的dumpmodule命令把代码dump出来，然后用reflector反编译找到相关代码。当然，如果客户愿意，他们直接提供源代码，那就更好了。

如果仔细比较上面三个!runaway的结果，你会发现时间是0，5，10秒。实际上我基本上就是按照这个时间进度来抓的dump。在生产环境下，大家还是每隔2、3分钟抓一次为好。
这个cpu high稍微简单一下。复杂的情况下，我们会发现几十号或者几百号threads，那么抓dump下来后，比较三个dump每个!runaway的前10个结果（基本差不多这个数字），找到重复的threads，然后看code，就能发现问题了。