lbq1221119

下午，msn上面一個(gè)朋友發(fā)了一個(gè)dump文件過來，說是Web服務(wù)器的CPU使用率在100%，找不到問題在什么地方，讓幫忙看看，遂讓把dump文件傳過來，找找問題出在哪兒。

       Framework2.0，Windows 2k的OS。

       加載了Dump文件之后，接著加載2.0版本的SOS擴(kuò)展調(diào)試模塊：

       .load C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\SOS.dll

       習(xí)慣性的列出托管線程：

       !threads

       發(fā)現(xiàn)報(bào)告以下錯(cuò)誤：

 

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以下，發(fā)現(xiàn)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

 

瞟了一下網(wǎng)絡(luò)流量，30kb/s，這個(gè)時(shí)候正在從符號文件服務(wù)器上面下符號文件呢。過了一會(huì)，需要的符號文件都下載好了：

首先看看線程池里面的情況：

 

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時(shí)間的使用情況：

 

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   

嗯，主要是用戶的應(yīng)用程序把Process Time給占用了。接著就看看到底是那個(gè)線程把User Mode的CPU時(shí)間都給用掉了：

 

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這么多時(shí)間，Thread 12一個(gè)人就占用0 days 0:06:27.109這么多時(shí)間，好吧，來看看私下到底干了什么：

 

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

 

切換完了之后，查看調(diào)用堆棧：

 

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這個(gè)地方，都沒有發(fā)現(xiàn)有啥異常的，比較標(biāo)準(zhǔn)的一個(gè)初始化并且執(zhí)行特定任務(wù)的Worker Thread的調(diào)用堆棧的最開始的部分，比較正常的說。然后就剩下stack的頂部的兩個(gè)調(diào)用：

 

06a8efb4 051d4b92 0x51dc0be

06a8f068 03530d1f 0x51d4b92

 

這個(gè)沒有顯示到底是什么方法，好吧，用SOS的列出托管方法調(diào)用堆棧看看：

 

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]

 

這個(gè)時(shí)候，最上面的三行調(diào)用估計(jì)就是問題的關(guān)鍵所在了。依照以往的經(jīng)驗(yàn)，有幾種性能調(diào)試的時(shí)候的現(xiàn)象比較常見：

l         CPU使用率高，內(nèi)存使用率不高

l         CPU使用率高，內(nèi)存某個(gè)模塊或者線程占用比較離譜

l         CPU和內(nèi)存使用都不高，就是網(wǎng)頁打開特別慢

對這幾個(gè)現(xiàn)象一般出現(xiàn)問題的大致原因和一個(gè)常用的分析套路，大致問題會(huì)出現(xiàn)在哪兒，了解下對這個(gè)時(shí)候的判斷還是比較有用的。:)

 

單從上面的調(diào)用堆棧來看，應(yīng)該是代碼里面寫的程序出現(xiàn)了問題，好吧，老娘是好欺負(fù)的么？

把一個(gè)module從一個(gè)dump文件里面分離出來的語法：

 

!SaveModule <Base address> <Filename>

<Base address>可以有好些辦法都可以得到，可以使用dumpDomain命令查看在AppDomain里面查看加載了哪些Module，下面是截取!DumpDomain的一條記錄，根據(jù)上面的堆棧顯示，就找RSWebGis這個(gè)模塊：

 

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這個(gè)模塊的base地址。當(dāng)然，這個(gè)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個(gè)section，全部剝奪了出來。

 

抄起Reflector反編譯，首先找到

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

這個(gè)的實(shí)現(xiàn)：

 

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);

}

我的個(gè)天，這個(gè)括號怎么這么多，我看的叫一個(gè)眼花。最開始的時(shí)候，估計(jì)問題是在這個(gè)地方，出現(xiàn)了邏輯錯(cuò)誤，瞅了半天，也找不到個(gè)所以然，這判斷也沒啥問題啊，就是幾個(gè)括號致使和正常的判斷邏輯有點(diǎn)偏差，但是也不至于是百分之一百的CPU占用率啊，然后問zhaochangj兄要這個(gè)方法的程序代碼，結(jié)果發(fā)現(xiàn)是：

 

#region 從字節(jié)數(shù)組中從指定的位置開始取一個(gè)長整型

        /// <summary>

        /// 取得數(shù)據(jù)包的大小

        /// </summary>

        /// <param name="bytes">指定的數(shù)據(jù)包</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)

  

看來這個(gè)Reflector對付這種很多括號的時(shí)候，厄，會(huì)有點(diǎn)短路。

好吧，既然這個(gè)沒有問題，就看上面是如何調(diào)用這個(gè)的：

 

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循環(huán)，呵呵，特別需要注意下，當(dāng)前這種情況很多時(shí)候都可能是特定情況下的死循環(huán)，當(dāng)然，不是全部。

 

 正在納悶這個(gè)定義的dataLong變量，第一次使用的時(shí)候是沒賦值的，這樣編譯器是有錯(cuò)誤提示的啊，而且i += dataLong這種寫法是第一次在for循環(huán)里面看到…遂上msn問問zhaochangj這段代碼是做啥用的，然后發(fā)過來了這個(gè)函數(shù)的這段源碼：

 

while (offSet < bytesTotal)

{

int length = GetDataLong(byteData, offSet);

byte[] tmpMsg;

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

{

//略

             

終于問題找到了：如果GetDataLong這個(gè)方法的返回值是0的時(shí)候，就會(huì)導(dǎo)致循環(huán)一直繼續(xù)下去，也就是for (int i = 0; i < length; i += dataLong)在程序的時(shí)候，如果dataLong返回的是0，也就是格式化一個(gè)長度小于4的byte串的時(shí)候，循環(huán)就會(huì)一直繼續(xù)下去。

 

Sum：這里只是描述了網(wǎng)站在發(fā)布以后，由CPU和內(nèi)存以及訪問速度出現(xiàn)特別慢的情況下徒手Windbg找問題的大致思路，具體情況具體問題可能啥樣都有，具體問題具體對待吧。

 

2008-6-17 11:30:20 PM 首發(fā)sscli.cnblogs.com & debug.cnblogs.com