zoukankan      html  css  js  c++  java
  • WinDbg调试CPU占用高的问题 试验+实战 《第七篇》

    一、High CPU试验

      1、示例代码

            static void Main(string[] args)
            {
                Console.Clear();
                Console.WriteLine("到命令行下,切换到windbg目录,执行adplus -hang -pn highcpu.exe -o c:\dumps");
                Console.WriteLine("如果要停止,按Ctrl+C结束程序");
                Console.WriteLine("====================================================");
                
                while (true)
                {
                    Console.SetCursorPosition(0, 3);
                    Console.Write(DateTime.Now.Ticks.ToString());
                }
    
                Console.ReadKey();
            }

      2、运行控制台程序后,抓取3次Dump,最好每次间隔几分钟。

      3、分别对每个Dump执行如下指令。

    第一个Dump:
    0:000> .load clr20sos.dll
    0:000> !runaway
     User Mode Time
      Thread       Time
       0:334       0 days 0:00:00.468
       3:dc8       0 days 0:00:00.000
       2:14d0      0 days 0:00:00.000
       1:750       0 days 0:00:00.000
    
    第二个Dump:
    0:000> .load clr20sos.dll
    0:000> !runaway
     User Mode Time
      Thread       Time
       0:334       0 days 0:00:08.221
       3:dc8       0 days 0:00:00.000
       2:14d0      0 days 0:00:00.000
       1:750       0 days 0:00:00.000
    
    第三个Dump:
    0:000> .load clr20sos.dll
    0:000> !runaway
     User Mode Time
      Thread       Time
       0:334       0 days 0:00:11.559
       3:dc8       0 days 0:00:00.000
       2:14d0      0 days 0:00:00.000
       1:750       0 days 0:00:00.000

      从上面的输出可以看到,线程0的CPU时间不断增加,CPU高占用很可能是由于线程0正在执行的代码有问题造成的。

      可以用!clrstack命令查看一下当前的调用堆栈以及其上的局部变量和值。

      当执行!clrstack时,报出了如下提示:

    0:000> !clrstack
    Failed to find runtime DLL (mscorwks.dll), 0x80004005
    Extension commands need mscorwks.dll in order to have something to do.

      这不是我想要的,加载mscorwks失败。后来经过调试发现,原来是第一步就.load时就错了,因为我的那段代码用的是vs2010。所以应该加载.net frameword 4.0。

      所以,最初应该执行的.load C:/WINDOWS/Microsoft.NET/Framework/v4.0.30319/sos.dll

      然后在执行!clrstack

      第三个Dump

    0:000> !clrstack
    *** ERROR: Symbol file could not be found.  Defaulted to export symbols for clr.dll - 
    PDB symbol for clr.dll not loaded
    OS Thread Id: 0x334 (0)
    Child SP       IP Call Site
    001cf2b8 779e70f4 [InlinedCallFrame: 001cf2b8] 
    001cf2b4 6a14672e *** WARNING: Unable to verify checksum for mscorlib.ni.dll
    DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, COORD)
    001cf2b8 6a1b6cfd [InlinedCallFrame: 001cf2b8] Microsoft.Win32.Win32Native.SetConsoleCursorPosition(IntPtr, COORD)
    001cf2ec 6a1b6cfd System.Console.SetCursorPosition(Int32, Int32)
    001cf324 005500bb *** WARNING: Unable to verify checksum for ConsoleApplication3.exe
    ConsoleApplication3.Program.Main(System.String[]) [C:UsersChenZhuodocumentsvisual studio 2010ProjectsConsoleApplication3ConsoleApplication3Program.cs @ 22]
    001cf4dc 70a33e22 [GCFrame: 001cf4dc] 

      第二个Dump

    0:000> !clrstack
    *** ERROR: Symbol file could not be found.  Defaulted to export symbols for clr.dll - 
    PDB symbol for clr.dll not loaded
    OS Thread Id: 0x334 (0)
    Child SP       IP Call Site
    001cf2b8 779e70f4 [InlinedCallFrame: 001cf2b8] 
    001cf2b4 6a14672e *** WARNING: Unable to verify checksum for mscorlib.ni.dll
    DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, COORD)
    001cf2b8 6a1b6cfd [InlinedCallFrame: 001cf2b8] Microsoft.Win32.Win32Native.SetConsoleCursorPosition(IntPtr, COORD)
    001cf2ec 6a1b6cfd System.Console.SetCursorPosition(Int32, Int32)
    001cf324 005500bb *** WARNING: Unable to verify checksum for ConsoleApplication3.exe
    ConsoleApplication3.Program.Main(System.String[]) [C:UsersChenZhuodocumentsvisual studio 2010ProjectsConsoleApplication3ConsoleApplication3Program.cs @ 22]
    001cf4dc 70a33e22 [GCFrame: 001cf4dc] 

      第一个Dump:

    0:000> !clrstack
    *** ERROR: Symbol file could not be found.  Defaulted to export symbols for clr.dll - 
    PDB symbol for clr.dll not loaded
    OS Thread Id: 0x334 (0)
    Child SP       IP Call Site
    001cf2b8 779e70f4 [InlinedCallFrame: 001cf2b8] 
    001cf2b4 6a14672e *** WARNING: Unable to verify checksum for mscorlib.ni.dll
    DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, COORD)
    001cf2b8 6a1b6cfd [InlinedCallFrame: 001cf2b8] Microsoft.Win32.Win32Native.SetConsoleCursorPosition(IntPtr, COORD)
    001cf2ec 6a1b6cfd System.Console.SetCursorPosition(Int32, Int32)
    001cf324 005500bb *** WARNING: Unable to verify checksum for ConsoleApplication3.exe
    ConsoleApplication3.Program.Main(System.String[]) [C:UsersChenZhuodocumentsvisual studio 2010ProjectsConsoleApplication3ConsoleApplication3Program.cs @ 22]
    001cf4dc 70a33e22 [GCFrame: 001cf4dc] 

      不知道为什么,我的第三个Dump并没有出现HighCPU的提示,也许是我的电脑配置有点高吧。不过,出问题的代码已可以看得到,就在Main方法里。只需要细细查看Main方法找到问题所在就OK了。

      学习自:http://www.cnblogs.com/juqiang/archive/2008/01/11/1035689.html

    二、High CPU问题实战

      公司的系统最近每隔一段时间就会突然变卡,CPU暴增,24核的CPU经常跑到25%,系统卡得不能动。项目经理终于忍不住了,叫我排查一下。

      首先,抓了3个DUMP,都是在系统卡的时候,隔个几分钟抓一次。

      由于服务器是64位的系统,而我的Win7是32位的系统,感觉老是有问题,一方面由于自己还是一个新手,很多问题一碰到就茫然,干脆直接偷偷在服务器装了个Windbg。

      首先,装载如sos.dll

    .load C:WindowsMicrosoft.NETFramework64v2.0.50727sos.dll

      然后逐个执行"!runaway"然后看下线程的CPU时间:

    第一个DUMP:
    47:4690 0 days 0:10:08.887 83:6914 0 days 0:08:52.727 46:6c88 0 days 0:04:13.813 45:a4d0 0 days 0:04:01.037 40:6d94 0 days 0:03:51.146 44:1c60 0 days 0:03:46.341 39:3fdc 0 days 0:03:46.107 37:eb0 0 days 0:03:28.791 41:11c0 0 days 0:03:27.184 38:9858 0 days 0:03:20.898 49:7b90 0 days 0:03:09.759 第二个DUMP: 47:4690 0 days 0:11:39.570 83:6914 0 days 0:08:54.334 46:6c88 0 days 0:04:46.339 45:a4d0 0 days 0:04:32.518 40:6d94 0 days 0:04:24.889 44:1c60 0 days 0:04:21.894 39:3fdc 0 days 0:04:21.863 37:eb0 0 days 0:04:00.335 41:11c0 0 days 0:03:57.495 38:9858 0 days 0:03:52.753 49:7b90 0 days 0:03:39.353 第三个DUMP: 47:4690 0 days 0:13:01.050 83:6914 0 days 0:08:55.645 46:6c88 0 days 0:05:16.089 45:a4d0 0 days 0:04:59.334 40:6d94 0 days 0:04:55.668 39:3fdc 0 days 0:04:53.328 44:1c60 0 days 0:04:53.079 37:eb0 0 days 0:04:31.800 41:11c0 0 days 0:04:26.496 38:9858 0 days 0:04:20.568 49:7b90 0 days 0:04:06.169

      很明显47号线程占用CPU时间非常厉害。

      查看一下特殊线程:

    0:000> !threads -special
    ThreadCount: 32
    UnstartedThread: 0
    BackgroundThread: 32
    PendingThread: 0
    DeadThread: 0
    Hosted Runtime: no
                                                  PreEmptive                                                Lock
           ID OSID        ThreadOBJ     State   GC     GC Alloc Context                  Domain           Count APT Exception
    ...
      83   18 6914 0000000009e7e190   180b220 Enabled  0000000000000000:0000000000000000 000000000372e6e0     1 MTA (Threadpool Worker)
    ...
    
           OSID     Special thread type
       47   4690    GC 
    ...
       83   6914    ThreadpoolWorker 
    ...

      从输出可以看到,47号线程是一个GC线程。有点眉目了,看到问题的情况极有可能是GC频繁引起的CPU升高。

      我们执行如下命令,查看所有线程的调用堆栈:

    0:000> ~* kb
    ...
    83 Id: 7558.6914 Suspend: 0 Teb: 000007ff`ffe56000 Unfrozen RetAddr : Args to Child : Call Site 000007fe`fd6d10dc : 00000002`2f3cfe10 00000001`5faa1eb0 00000000`11606268 000007fe`fd6d64da : ntdll!ZwWaitForSingleObject+0xa 000007fe`f128d0e0 : 00000000`ffffffff 00000000`ffffffff 00000002`00000000 00000000`00000460 : KERNELBASE!WaitForSingleObjectEx+0x79 000007fe`f128d1e3 : 00000000`00000000 00000000`09e7e190 00000000`00000000 00000000`ffffffff : mscorwks!MethodTableBuilder::MethodSignature::GetMethodAttributes+0xa8 000007fe`f138e250 : 00000000`0b65c640 000007fe`f138e289 0000739d`00000004 00000000`00000001 : mscorwks!CLREvent::WaitEx+0x63 000007fe`f15a9596 : 00000000`00064000 000007fe`f129b6cb ffffffff`fffffffe 000007fe`f1286920 : mscorwks!SVR::gc_heap::wait_for_gc_done+0x80 000007fe`f17339cc : 00000000`00000007 000007fe`f129b6ef 00000001`1ff9e250 00000000`00064930 : mscorwks!SVR::GCHeap::GarbageCollectGeneration+0x206 000007fe`f13996a2 : 00000000`00000000 00000000`0b65c810 00000000`00064930 000007fe`00000007 : mscorwks!SVR::gc_heap::try_allocate_more_space+0x1ac 000007fe`f136ecef : 00000000`00000002 00000000`00000000 00000000`00000038 00000000`00000038 : mscorwks!SVR::gc_heap::allocate_more_space+0x32 000007fe`f12d7278 : 00000000`00000038 00000000`00000038 00000000`09e7e1f8 000007fe`f12d71b1 : mscorwks!SVR::gc_heap::allocate_large_object+0x5f 000007fe`f12d758e : 00000000`010b25e0 00000002`838d92c8 00000000`0006492c 00000000`0003248a : mscorwks!SVR::GCHeap::Alloc+0x198 000007fe`f17b9433 : 00000001`7f8ce378 00000000`09e7e190 00000000`0b65c9a8 00000000`09e7e190 : mscorwks!SlowAllocateString+0x7e 000007fe`f051beec : 00000000`00032489 00000000`00000000 00000000`00000000 00000000`00000002 : mscorwks!FramedAllocateString+0xd3 000007ff`00cf0313 : 00000001`5f3ecd98 00000001`1ff9e098 00000002`55400368 00000000`00000000 : mscorlib_ni+0x2ebeec 000007ff`012b0ac5 : 00000001`5f3ecd98 00000001`5f418988 00000001`ff350370 00000002`4f89cd50 : 0x7ff`00cf0313
    ...

      这时输出的内容可能非常多,但是没关系,我们关注的只是哪个线程引起的GC,我们可以在返回中检索一下GarbageCollectGeneration就OK了,这个是GC的入口函数。

      检索到是83号线程,那么为什么83号线程会触发GC呢?我们切换到线程83。

    0:000> ~83s
    ntdll!ZwWaitForSingleObject+0xa:
    00000000`776712fa c3              ret

      查看线程的调用堆栈:

    0:083> !clrstack
    OS Thread Id: 0x6914 (83)
    Child-SP         RetAddr          Call Site
    000000000b65cae0 000007ff00cf0313 System.String.Concat(System.String, System.String, System.String)
    000000000b65cb40 000007ff012b0ac5 xxx.TE.Web.Service.Management.CompositeFieldService.GetCompositeFieldContent(System.Web.HttpContextBase, System.String, TE.Web.Domain.Management.CompositeField, Int32)
    000000000b65cfd0 000007ff0126d39b TE.Web.Areas.Cases.Controllers.WritDataBagController.PageWritContent(System.String, Int32)
    000000000b65d410 000007fee7ca082c DynamicClass.lambda_method(System.Runtime.CompilerServices.ExecutionScope, System.Web.Mvc.ControllerBase, System.Object[])
    000000000b65d460 000007fee7ca31ef System.Web.Mvc.ReflectedActionDescriptor.Execute(System.Web.Mvc.ControllerContext, System.Collections.Generic.IDictionary`2<System.String,System.Object>)
    000000000b65d4c0 000007fee7ca47b5 System.Web.Mvc.ControllerActionInvoker.InvokeActionMethod(System.Web.Mvc.ControllerContext, System.Web.Mvc.ActionDescriptor, System.Collections.Generic.IDictionary`2<System.String,System.Object>)
    000000000b65d500 000007fee7ca354f System.Web.Mvc.ControllerActionInvoker+<>c__DisplayClassd.<InvokeActionMethodWithFilters>b__a()
    000000000b65d560 000007fee7ca3780 System.Web.Mvc.ControllerActionInvoker.InvokeActionMethodFilter(System.Web.Mvc.IActionFilter, System.Web.Mvc.ActionExecutingContext, System.Func`1<System.Web.Mvc.ActionExecutedContext>)
    000000000b65d5f0 000007fee7ca3186 System.Web.Mvc.ControllerActionInvoker.InvokeActionMethodWithFilters(System.Web.Mvc.ControllerContext, System.Collections.Generic.IList`1<System.Web.Mvc.IActionFilter>, System.Web.Mvc.ActionDescriptor, System.Collections.Generic.IDictionary`2<System.String,System.Object>)
    000000000b65d650 000007fee7ca9f5d System.Web.Mvc.ControllerActionInvoker.InvokeAction(System.Web.Mvc.ControllerContext, System.String)
    000000000b65d6f0 000007fee7c9b8f0 System.Web.Mvc.Controller.ExecuteCore()
    000000000b65d750 000007fee7c9c245 System.Web.Mvc.MvcHandler+<>c__DisplayClass8.<BeginProcessRequest>b__4()
    000000000b65d790 000007fee7cd4c7f System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass1.<MakeVoidDelegate>b__0()
    000000000b65d7d0 000007fee7c9c035 System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass8`1[[System.Web.Mvc.Async.AsyncVoid, System.Web.Mvc]].<BeginSynchronous>b__7(System.IAsyncResult)
    000000000b65d800 000007fee7c9b7e3 System.Web.Mvc.Async.AsyncResultWrapper+WrappedAsyncResult`1[[System.Web.Mvc.Async.AsyncVoid, System.Web.Mvc]].End()
    000000000b65d840 000007feecab5576 System.Web.Mvc.MvcHandler.EndProcessRequest(System.IAsyncResult)
    000000000b65d870 000007feeca78867 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
    000000000b65d920 000007feed16e8f1 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
    000000000b65d9c0 000007feed15ef52 System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
    000000000b65db50 000007feed140749 System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)
    000000000b65dba0 000007feed2713a1 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
    000000000b65dcc0 000007feed270f6b System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
    000000000b65de40 000007feed270e34 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
    000000000b65dea0 000007fef141b08a DomainNeutralILStubClass.IL_STUB(Int64, Int64, Int64, Int32)
    000000000b65e6d0 000007feed2714d0 DomainNeutralILStubClass.IL_STUB(IntPtr, System.Web.RequestNotificationStatus ByRef)
    000000000b65e7b0 000007feed270f6b System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
    000000000b65e930 000007feed270e34 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
    000000000b65e990 000007fef141b2db DomainNeutralILStubClass.IL_STUB(Int64, Int64, Int64, Int32)

      发现到String.Concat就没了,从代码猜测,可能是程序在做字符串拼接,申请内存不到,所以才会触发强烈的GC操作。我们来看看该线程上的内存分配:

    0:083> !dso
    OS Thread Id: 0x6914 (83)
    RSP/REG          Object           Name
    000000000b65c470 000000022f3cfe10 System.Web.HttpApplication+PipelineStepManager
    000000000b65c8a8 00000002838d92c8 System.String
    000000000b65ca10 000000014f620fe0 System.String
    000000000b65ca18 00000002838d92c8 System.String
    000000000b65ca20 000000014f621260 System.String
    000000000b65ca38 000000022f3cfe10 System.Web.HttpApplication+PipelineStepManager
    000000000b65ca98 000000022f3cfe10 System.Web.HttpApplication+PipelineStepManager
    000000000b65caa0 000000022f3cfe10 System.Web.HttpApplication+PipelineStepManager
    000000000b65cab0 00000001dfc47d28 System.String
    000000000b65cab8 000000014f621260 System.String
    000000000b65cad0 000000014f620fe0 System.String
    000000000b65cb00 000000014f620fe0 System.String
    000000000b65cb30 000000014f620fe0 System.String
    000000000b65cb40 000000015f3ecd98 TE.Web.Service.Management.CompositeFieldService
    000000000b65cb98 0000000287523340 System.String
    000000000b65cba0 000000024f89d1f0 System.Collections.Generic.List`1[[xxx.TE.Web.Domain.Management.CompositeField, xxx.TE.Web.Domain]]
    000000000b65cbb8 000000024f89d218 TE.Web.Domain.Management.CompositeField
    000000000b65cbc0 000000024f89db28 System.Text.RegularExpressions.Regex
    000000000b65cbc8 000000024f89e028 System.Text.RegularExpressions.MatchCollection
    000000000b65cbd0 000000011fb05380 System.Collections.Hashtable
    000000000b65cbd8 000000011fb05238 System.String
    000000000b65cbe0 000000011fb05288 System.String
    ...

      由于线程堆栈是执行到字符串就停止了,所以我们找几个字符串试试运气,从最上面(最后)分配的开始:

    0:083> !objsize 00000002838d92c8
    sizeof(00000002838d92c8) =       411936 (     0x64920) bytes (System.String)

      400多K的字符串,打开来看下这个字符串里面是些什么?

    0:083> !do 00000002838d92c8
    Name: System.String
    MethodTable: 000007fef0667d90
    EEClass: 000007fef026e560
    Size: 411932(0x6491c) bytes
     (C:WindowsassemblyGAC_64mscorlib2.0.0.0__b77a5c561934e089mscorlib.dll)
    String: 粤A87xxx,粤ACxxx挂......
    Fields:
                  MT    Field   Offset                 Type VT     Attr            Value Name
    000007fef066f000  4000096        8         System.Int32  1 instance           205954 m_arrayLength
    000007fef066f000  4000097        c         System.Int32  1 instance           205953 m_stringLength
    000007fef06697d8  4000098       10          System.Char  1 instance             7ca4 m_firstChar
    000007fef0667d90  4000099       20        System.String  0   shared           static Empty
                                     >> Domain:Value  000000000112bef0:00000001ff350370 000000000372e6e0:00000001ff350370 <<
    000007fef0669688  400009a       28        System.Char[]  0   shared           static WhitespaceChars
                                     >> Domain:Value  000000000112bef0:00000001ff350b60 000000000372e6e0:00000001ff3588e8 <<

      做到这里,本次系统变卡的原因貌似已经有一个说法已经说得过去了,就是Asp.net尝试分配一个大对象,.Net中超过85Kb就叫大对象。但是内存不足,于是触发GC回收,回收不到一个400Kb长的内存块,于是报了一个内存溢出异常。

        这个道理乍一看,似乎说得通,但是实际上很诡异,.Net上只是使用了2G左右的内存,一共24G内存的服务器为什么只是用了2G内存,GC拼命回收垃圾呢?为什么只是用了2G内存就分配不出400KB的内存了呢? 

        在这个地方,卡住了,中途以为是内存频繁分配造成大量碎片,往内存碎片方向跟过,最后确定与内存碎片无关。原因是不相信这个东西。因为服务器是24CPU24G内存。24G内存使用了2G内存就出现这个问题。

        这个问题想了两天,百思不得其解。后来,又无意中发现了一个小苗头。

    !dumpheap -stat
    0:000> !dumpheap -stat
    ------------------------------
    …
    000007fef0668168        1      136  System.OutOfMemoryException
    …
    000007fef066f8b0  67392    46915920System.Collections.Hashtable+bucket[]
    000007fef0667d90  291003    96055608 System.String
    Total 2737406 objects
    Fragmented blocks larger than 0.5 MB:
              Addr    Size      Followed by
    000000014f92ff10    4.2MB 000000014fd5c698 System.String
    000000019fb89940    6.3MB 00000001a01d57b8 System.Threading.OverlappedData
    000000020fb18698    5.7MB 00000002100ccc70 System.Threading.Overlapped

      在上千行的返回结果中,居然无意中瞟到一个System.OutOfMemoryException。熟悉C#的应该都知道,这个是内存溢出异常,当内存不足时才会发生。

      本来说分配不出400KB内存我还很怀疑,现在又无意中从上千行的返回结果中瞟到这一行代码。确定是内存问题,于是怀疑是Asp.net配置文件不正确,导致系统最多只能够用到2G内存呢?因为Asp.net Web.Config里面的processModel节点有个memoryLimit参数,可以设置Asp.net能够使用的最大内存。但是从网站一直跟到服务器的配置文件,都没有发现有设置该参数,也就是说,Asp.net使用默认设置是60%。24G*60%最大是能够使用14G左右的内存。 太诡异了,实在想不通。最后,只有碰碰运气了,随便输入些变量看看值有没有什么问题。(实际上本处也有章法可依,如果此时找到不问题,最应该就是找到这次请求的参数,重现与当时客户一样的操作),当随手在输入如下命令之后,突然眼前一亮。

      依次执行如下3个指令:

    0:083> !do 000000015f416b08  //换了个DUMP,本来这个地址是出现在 !dso命令里的
    Name: System.Web.HttpContext
    MethodTable: 000007feecc075c8
    EEClass: 000007feec862438
    Size: 336(0x150) bytes
    (C:WindowsassemblyGAC_64System.Web2.0.0.0__b03f5f7f11d50a3aSystem.Web.dll)
    Fields:
                  MT    Field  Offset                Type VT    Attr            Value Name
    000007feecc0a0f0  4000fe6      8 ...IHttpAsyncHandler  0 instance0000000000000000 _asyncAppHandler
    000007feecc09c20 4000fe7      10...b.HttpApplication  0 instance 000000022f3cc5d0 _appInstance
    000007feecc0a160 4000fe8      18....Web.IHttpHandler  0 instance 000000015f418c48 _handler
    000007feecc0a5a0  4000fe9      20 ...m.Web.HttpRequest  0instance 000000015f416c58 _request
    
    0:083> !do 000000015f416c58
    <Note: this object has an invalid CLASSfield>
    Name: System.Web.HttpRequest
    MethodTable: 000007feecc0a5a0
    EEClass: 000007feec863d30
    Size: 336(0x150) bytes
    (C:WindowsassemblyGAC_64System.Web2.0.0.0__b03f5f7f11d50a3aSystem.Web.dll)
    Fields:
                  MT    Field  Offset                Type VT    Attr            Value Name
    …
    000007feecb76150  4001095      c0...tpValueCollection  0 instance 000000015f417a80 _queryString
    …
    
    0:083> !do 000000015f418ec0
    Name: System.String
    MethodTable: 000007fef0667d90
    EEClass: 000007fef026e560
    Size: 90(0x5a) bytes
    (C:WindowsassemblyGAC_64mscorlib2.0.0.0__b77a5c561934e089mscorlib.dll)
    String:_=1400639407322&CaseCode=&Page=0
    Fields:
                  MT    Field  Offset                Type VT    Attr            Value Name
    000007fef066f000 4000096        8        System.Int32  1 instance              33 m_arrayLength

      以上3个命令,分明是找到HttpContext对象,再找到HttpContext对象的Reqest对象,再找到Request对象的QueryString(请求参数)

      留意CaseCode,居然是Null(由于我对此系统的逻辑还是比较熟悉的。知道CaseCode为Null是不正常的情况)怎么可能呢。用户是怎样操作出来的呢?

        打开系统办案台,找到文书随便点一下。最后终于发现,如果用户在相应文书上选择在新窗口中打开(IE中是鼠标单击的时候轻轻拖了一下),就能够发起这样的请求。

          So,我直接在线上的系统模仿了几次这样的操作,并且紧紧盯着资源监视器。发现,在40分钟之后(2424G内存果然不是盖的)w3wp.exe的内存已经上升到了5G。随后,系统就变慢,跟之前的症状一模一样。

        于是,打开本地的代码,找到相应的代码段。

        //[HttpPost]为提高性能用GET提交方式
        publicActionResult PageWritContent(string CaseCode, intPage)
        {…}

      此处设置为了允许Get请求,这没什么不妥,但是当我模拟用户操作的时候,进一步跟踪发现,当CaseCode为Null的时候,系统的SQL语句如下:

    select xxx,xxx,xx,xxx,xxxfrom xxx
    where 1 = 1
    and (xxx = 1 or xxx = 0)
    and xxx = 0

      这个SQL语句相当于把整个数据库的案件都查出来了。更重要的是,还关联查出了xxx,xxx,xxx,xxx,xxx,xxx,xxx等7张关联表的数据。说白了就是,把系统这几年的数据都翻出来了。由于数据比较敏感,把表名,字段之类的都用xxx代替了。

      当在本地执行相同操作时,Visual Studio输出栏拼命地输出查询语句数千行。

        整个问题的来龙去脉是:由于代码逻辑不严谨,导致当缺少参数时,把整个数据库的数据都查询出来,内存不足,.Net的垃圾回收机制启动,尽职尽责的GC努力回收内存,导致CPU飙升,系统运行变慢,甚至卡死,造成客户端长时间无响应。同时,服务器内存是24G,分配给.Net应用程序池更少(不可能把整个数据库的案件全部读取到内存中),导致无论GC如何努力,最终都还是报出了一个OutMemoryException异常。问题终于水落石出。

        这个Bug比较隐晦。主要是引起Bug的操作并不会立即看到效果,而是过1、2个小时才会出现变卡的情况,所以很容易过了测试。而在调试阶段,如果程序员不是特别留意那几个页面,也很难会留意到这种问题。

        不得不说,通过抓DUMP来找到系统问题,这的确是一门手艺活。能够发现隐藏的比较深的Bug。

      检查过同类型的文书,发现有近一半的文书都是允许以Get方式加载文书,同时又不检查案件编号是否为空的情况,例如xxx文书,xxx文书等。因此,修正如下代码逻辑,在加载文书时,检查案件编号是否为空,当案件编号为空的时候,直接返回。而Get方式加载逻辑上并没有问题,保留也可。

        至此,暂时已经解决系统突然变慢的一个问题,下一步就是把代码更新上服务器之后观察一段时间,看还会不会出现有高CPU或内存溢出的其他问题。

  • 相关阅读:
    用户体验
    jsp ini 配置文件
    Highcharts 图表
    简单游戏服务器
    js 数据操作
    jquery 导航
    as3.0 删除子元件
    java float 保留二位小数
    局域网ip
    SWFUpload
  • 原文地址:https://www.cnblogs.com/kissdodog/p/3731476.html
Copyright © 2011-2022 走看看