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或内存溢出的其他问题。

  • 相关阅读:
    OPPO R9sPlus MIFlash线刷TWRP Recovery ROOT详细教程
    OPPO R11 R11plus系列 解锁BootLoader ROOT Xposed 你的手机你做主
    努比亚(nubia) M2青春版 NX573J 解锁BootLoader 并进入临时recovery ROOT
    华为 荣耀 等手机解锁BootLoader
    青橙 M4 解锁BootLoader 并刷入recovery ROOT
    程序员修炼之道阅读笔03
    冲刺8
    典型用户模板分析
    学习进度八
    冲刺7
  • 原文地址:https://www.cnblogs.com/kissdodog/p/3731476.html
Copyright © 2011-2022 走看看