下午，msn上面一个朋友发了一个dump文件过来，说是Web服务器的CPU使用率在100%，找不到问题在什么地方，让帮忙看看，遂让把dump文件传过来，找找问题出在哪儿。

Framework2.0，Windows 2k的OS。

加载了Dump文件之后，接着加载2.0版本的SOS扩展调试模块：

.load C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\SOS.dll<?xml:namespace prefix = o ns = "urn:schemas-microsoft-com:office:office" />

习惯性的列出托管线程：

!threads

发现报告以下错误：

Unable to load image

C:\WINDOWS\assembly\NativeImages_v2.0.50727_64\mscorlib\339a2c337cdafd47f2ba740bb03f9718\mscorlib.ni.dll, Win32 error 2

*** WARNING: Unable to verify checksum for mscorlib.ni.dll

lm以下，发现symbol文件都没加载上来，于是.reload一下，我配置的符号文件路径如下：

C:\WINDOWS\Symbols;C:\Program Files\Microsoft Visual Studio8

\SDK\v2.0\symbols;srv*E:\bak\symbols*http://msdl.microsoft.com/download/symbols

瞟了一下网络流量，30kb/s，这个时候正在从符号文件服务器上面下符号文件呢。过了一会，需要的符号文件都下载好了：

首先看看线程池里面的情况：

0:000> !threadpool

CPU utilization 100%

Worker Thread: Total: 1 Running: 0 Idle: 1 MaxLimit: 100 MinLimit: 1

Work Request in Queue: 0

--------------------------------------

Number of Timers: 8

--------------------------------------

Completion Port Thread:Total: 1 Free: 1 MaxFree: 2 CurrentLimit: 1 MaxLimit: 100 MinLimit: 1

厄，CPU占用率果然在百分之一百啊。

看看cpu时间的使用情况：

0:000> .time

Debug session time: Thu Jun 12 08:59:14.000 2008 (GMT+8)

System Uptime: 2 days 1:01:08.081

Process Uptime: 2 days 0:30:27.000

Kernel time: 0 days 0:00:22.000

User time: 0 days 0:09:40.000

嗯，主要是用户的应用程序把Process Time给占用了。接着就看看到底是那个线程把User Mode的CPU时间都给用掉了：

0:000> !runaway

User Mode Time

Thread       Time

12:b9c       0 days 0:06:27.109

2:b54       0 days 0:00:50.468

15:f98       0 days 0:00:09.937

10:b94       0 days 0:00:03.531

5:b6c       0 days 0:00:01.937

11:b98       0 days 0:00:01.671

3:b58       0 days 0:00:01.171

0:b44       0 days 0:00:00.640

9:b84       0 days 0:00:00.265

7:b7c       0 days 0:00:00.203

14:388       0 days 0:00:00.000

13:b68       0 days 0:00:00.000

8:b80       0 days 0:00:00.000

6:b78       0 days 0:00:00.000

4:b5c       0 days 0:00:00.000

1:b50       0 days 0:00:00.000

User Time一共是0 days 0:09:40.000这么多时间，Thread 12一个人就占用0 days 0:06:27.109这么多时间，好吧，来看看私下到底干了什么：

0:000> ~12s

eax=000007ff ebx=00000000 ecx=0112d894 edx=013055ac esi=013055ac edi=dbb83137

eip=051dc0be esp=06a8ef48 ebp=06a8efb4 iopl=0         nv up ei pl nz ac pe nc

cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000216

051dc0be 3bf8            cmp     edi,eax

切换完了之后，查看调用堆栈：

0:012> k

ChildEBP RetAddr

WARNING: Frame IP not in any known module. Following frames may be wrong.

06a8efb4 051d4b92 0x51dc0be

06a8f068 03530d1f 0x51d4b92

06a8f080 79e7c74b mscorlib_ni+0x2f0d1f

06a8f090 79e7c6cc mscorwks!CallDescrWorker+0x33

06a8f110 79e7c8e1 mscorwks!CallDescrWorkerWithHandler+0xa3

06a8f24c 79e7c783 mscorwks!MethodDesc::CallDescr+0x19c

06a8f268 79e7c90d mscorwks!MethodDesc::CallTargetWorker+0x1f

06a8f27c 79eb300f mscorwks!MethodDescCallSite::Call_RetArgSlot+0x18

06a8f448 79eb2f31 mscorwks!ExecuteCodeWithGuaranteedCleanupHelper+0x9b

06a8f4f8 034f3ff7

mscorwks!ReflectionInvocation::ExecuteCodeWithGuaranteedCleanup+0xf9

06a8f510 034f3ede mscorlib_ni+0x2b3ff7

06a8f528 03530c68 mscorlib_ni+0x2b3ede

06a8f540 79e7c74b mscorlib_ni+0x2f0c68

06a8f550 79e7c6cc mscorwks!CallDescrWorker+0x33

06a8f5d0 79e7c8e1 mscorwks!CallDescrWorkerWithHandler+0xa3

06a8f710 79e7c783 mscorwks!MethodDesc::CallDescr+0x19c

06a8f72c 79e7c90d mscorwks!MethodDesc::CallTargetWorker+0x1f

06a8f740 79fc58cd mscorwks!MethodDescCallSite::Call_RetArgSlot+0x18

06a8f928 79ef3207 mscorwks!ThreadNative::KickOffThread_Worker+0x190

06a8f93c 79ef31a3 mscorwks!Thread::DoADCallBack+0x32a

一直到CallDescrWorker这个地方，都没有发现有啥异常的，比较标准的一个初始化并且执行特定任务的Worker Thread的调用堆栈的最开始的部分，比较正常的说。然后就剩下stack的顶部的两个调用：

06a8efb4 051d4b92 0x51dc0be

06a8f068 03530d1f 0x51d4b92

这个没有显示到底是什么方法，好吧，用SOS的列出托管方法调用堆栈看看：

0:012> !clrstack

OS Thread Id: 0xb9c (12)

ESP       EIP

06a8ef48 051dc0be RSWebGis.RSProtocolClass.GetDataLong(Byte[], Int32)

06a8ef68 051dbf74 RSWebGis.RSProtocolClass.ParsePackage(Byte[])

06a8efbc 051d4b92 RSWebGis.RSProtocolClass.DoAnalysisWork()

06a8f070 03530d1f System.Threading.ThreadHelper.ThreadStart_Context(System.Object)

06a8f078 034f40ab System.Threading.ExecutionContext.runTryCode(System.Object)

06a8f49c 79e7c74b [HelperMethodFrame_PROTECTOBJ: 06a8f49c]

System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object)

06a8f504 034f3ff7

System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)

06a8f51c 034f3ede

System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)

06a8f534 03530c68 System.Threading.ThreadHelper.ThreadStart()

06a8f760 79e7c74b [GCFrame: 06a8f760]

06a8fa50 79e7c74b [ContextTransitionFrame: 06a8fa50]

这个时候，最上面的三行调用估计就是问题的关键所在了。依照以往的经验，有几种性能调试的时候的现象比较常见：

l         CPU使用率高，内存使用率不高

l         CPU使用率高，内存某个模块或者线程占用比较离谱

l         CPU和内存使用都不高，就是网页打开特别慢

对这几个现象一般出现问题的大致原因和一个常用的分析套路，大致问题会出现在哪儿，了解下对这个时候的判断还是比较有用的。:)

单从上面的调用堆栈来看，应该是代码里面写的程序出现了问题，好吧，老娘是好欺负的么？

把一个module从一个dump文件里面分离出来的语法：

!SaveModule <Base address> <Filename>

<Base address>可以有好些办法都可以得到，可以使用dumpDomain命令查看在AppDomain里面查看加载了哪些Module，下面是截取!DumpDomain的一条记录，根据上面的堆栈显示，就找RSWebGis这个模块：

Assembly: 001de3d0 [c:\WINNT\Microsoft.NET\Framework\v2.0.50727\Temporary

ASP.NETFiles\rswebgis\cbfaa214\c8518bb9\assembly\dl3\b000bb67\

2dae9f2e_ab93c801\RSWebGis.DLL

ClassLoader: 001dc518

SecurityDescriptor: 001de348

Module Name

05860010 c:\WINNT\Microsoft.NET\Framework\v2.0.50727\Temporary

ASP.NET Files\rswebgis\cbfaa214\c8518bb9\assembly\dl3\b000bb67\

2dae9f2e_ab93c801\RSWebGis.DLL

这里的05860010就是RSWebGis这个模块的base地址。当然，这个base Address还可以通过lm命令查看加载的module来获取。

好吧，剥离出来保存到C盘：

0:000>!SaveModule 05880000 c:\ RSWebGis.DLL.dll

4 sections in file

section 0 - VA=1000, VASize=e82da9, FileAddr=400, FileSize=e82e00

section 1 - VA=e84000, VASize=24d24, FileAddr=e83200, FileSize=ec00

section 2 - VA=ea9000, VASize=5a8, FileAddr=e91e00, FileSize=600

section 3 - VA=eaa000, VASize=c183c, FileAddr=e92400, FileSize=c1a00

一共4个section，全部剥夺了出来。

抄起Reflector反编译，首先找到

06a8ef48 051dc0be RSWebGis.RSProtocolClass.GetDataLong(Byte[], Int32)

这个的实现：

private int GetDataLong(byte[] bytes, int count)

{

if ((((count > (bytes.Length - 1)) || (count > (bytes.Length - 2))) || ((count >(bytes.Length - 3)) || (count > (bytes.Length - 4)))) || (count < 0))

{

return 0;

}

return BitConverter.ToInt32(bytes, count);

}

我的个天，这个括号怎么这么多，我看的叫一个眼花。最开始的时候，估计问题是在这个地方，出现了逻辑错误，瞅了半天，也找不到个所以然，这判断也没啥问题啊，就是几个括号致使和正常的判断逻辑有点偏差，但是也不至于是百分之一百的CPU占用率啊，然后问zhaochangj兄要这个方法的程序代码，结果发现是：

#region 从字节数组中从指定的位置开始取一个长整型

/// <summary>

/// 取得数据包的大小

/// </summary>

/// <param name="bytes">指定的数据包</param>

/// <param name="count">起始位置</param>

private int GetDataLong(byte[] bytes, int count)

{

if (count > bytes.Length - 1 || count > bytes.Length - 2 || count > bytes.Length - 3

|| count > bytes.Length - 4 || count < 0)

看来这个Reflector对付这种很多括号的时候，厄，会有点短路。

好吧，既然这个没有问题，就看上面是如何调用这个的：

private void ParsePackage(byte[] byteData)

{

int dataLong;

int length = byteData.Length;

for (int i = 0; i < length; i += dataLong)

{

dataLong = this.GetDataLong(byteData, i);

if (((i + dataLong) <= length) && (dataLong > 0))

{

long num4;

int num5;

int num6;

string str;

byte[] buffer;

byte[] buffer2;

this.CopyBytes(byteData, i, dataLong, out buffer2);

int start = 0;

if (((buffer2.Length - start) >= 15) && (this.TCPMsgHeadProc(buffer2, start,

out num4, out num5, out str, out num6, out buffer) == 0L))

{

this.m_noBackCount = 0;

this.TCPDataProc(num4, num5, str, num6, buffer);

}

}

}

}

厄，看到了for循环，呵呵，特别需要注意下，当前这种情况很多时候都可能是特定情况下的死循环，当然，不是全部。

正在纳闷这个定义的dataLong变量，第一次使用的时候是没赋值的，这样编译器是有错误提示的啊，而且i += dataLong这种写法是第一次在for循环里面看到…遂上msn问问zhaochangj这段代码是做啥用的，然后发过来了这个函数的这段源码：

while (offSet < bytesTotal)

{

int length = GetDataLong(byteData, offSet);

byte[] tmpMsg;

if ((offSet + length <= bytesTotal) && (length > 0))

{

//略

终于问题找到了：如果GetDataLong这个方法的返回值是0的时候，就会导致循环一直继续下去，也就是for (int i = 0; i < length; i += dataLong)在程序的时候，如果dataLong返回的是0，也就是格式化一个长度小于4的byte串的时候，循环就会一直继续下去。

Sum：这里只是描述了网站在发布以后，由CPU和内存以及访问速度出现特别慢的情况下徒手Windbg找问题的大致思路，具体情况具体问题可能啥样都有，具体问题具体对待吧。

2008-6-17 11:30:20 PM 首发sscli.cnblogs.com & debug.cnblogs.com