zoukankan      html  css  js  c++  java
  • High CPU in GC(都是+=惹的祸,为啥不用StringBuilder呢?)

    序 & 跋)

       此文及后面的系列,都是从tess老大那里翻译过来的。一直和GTEC的老牛们作CASE(此句有误,一直提CASE,等老牛们提供答案),算是粘到了一点仙气。偶一直比较懒,所以以前精心抄袭的文章,今天再次精心作序于此,希望对各位挣扎于现实与理想的各位,共享,共勉。tess老大的文章国内似乎有人翻译过,但偶个人观点,不看好,因为好东西都没了哦。

       不是我不舍得,意思是,我的post里面基本上没有link,但是从google上都能搞到,如tess老大的系列debug文章。写程序的人,用好google应该是第一要素啊,哇哈哈哈!(百度除外,偶鄙视的公司)

       每个post的题目都挺吓人,但是最终发现问题以及解决掉的方法,都异常简单。简单,产生丑陋。

     

    问题描述:

    程序慢的要死,CPU占用始终持续在70%-80%之间

    解决步骤:

    性能监视器。对于高CPU占用,一般的是这三个原因:

    ·         高的离谱的循环

    ·         太多的加载(比如,许多小的对象被频繁的处理)

    ·         GC作了太多的事情

    第一种情况,当你在恰当的时机抓到一个dump,就非常容易解决,一般而言,都是因为业务处理逻辑造成的。第二种情况,一般需要从硬件上考虑,scale up或者scale out,都行。

    是否是GC的问题,我们需要看性能监视器里面的.NET CLR Memory计数器。这里面,最重要的是.net CLR Memory / % Time in GC. 这个值的阀值,可能是5%或者30%或者20%。实际上,没有一个准确的阀值存在的。当然,这个数字理论上应该接近于0%才对。

    在GC里面,导致高CPU占用的原因,通常是因为过高的分配速率(对应到性能监视器里面的.net CLR Memory / allocated bytes/sec计数器。但实际上,如果所有的GC操作都在第0代上,则不会导致这个问题。真正的元凶,是大量的2代操作。如N多的对象在被移动到2代或者从2代中被释放。另一个原因就是我们熟知的大对象操作(LOH)

    再强调一次,没有什么准确的指标,就告诉我们,超过了它就是出问题了,这是不可能的。包括微软给我们的大多数Practics Training,只有“尽量”、“尽可能”、“如果”等,而不是“一定”、“必须”。

    如同我在那篇“浅谈GC中”讲到的一样,如果你搞了GC.Collect(2)或者GC.GetTotalMemory(true),那么也会导致大量的2代回收。

    对于这个问题,我从性能监视器中抓到了这些数据:

    % Time in GC                        ~40 % average
    allocated bytes / sec              400 MB average
    # Induced GC                        0
    # Gen 0 Collections                28.379
    # Gen 1 Collections                28.378
    # Gen 2 Collections                28.378

    看第二行,真是让人晕倒!每秒分配400M字节!但实际上,我的代码中没有分配任何这么大的东西,有点太离谱了吧?!如果看最后面三行,也比较搞笑,0、1、2代的分配几乎完全相同。这实际上说明有LOH在压缩,或者有大量的对象冲进了第2代,然后又被立刻释放掉。

    开始debug吧!

    GC问题很难debug,因为:

    1. 如果在GC中间过程中用adplus -hang模式抓了一个dump,基本上从dump里面看不到任何高CPU占用的原因。
    2. 即时你通过性能监视器找到了GC的问题,也抓到了dump,但是很难分析。

    实际上,通用的做法是每隔一小段时间,你就抓一次dump。如果看起来都差不多,那么有可能就能分析出哪里的问题了。

    步骤1 - 我们在GC里面不?

    如果我们的OS是server,那么每个CPU有一个GC线程(如果超线程的话,就是2个)。如果是非server的,那么只有一个GC线程。我们正在看到的这个dump,是在一个双核的、带有.NET2.0的机器上产生的。

    如果我们不在GC过程中,那么我们会有两个线程(每个CPU一个):

      18  Id: 134c.918 Suspend: 1 Teb: 7ffa8000 Unfrozen
    ChildEBP RetAddr  Args to Child             
    01e1fe68 7c822124 77e6baa8 00000398 00000000 ntdll!KiFastSystemCallRet
    01e1fe6c 77e6baa8 00000398 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
    01e1fedc 79e77fd1 00000398 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
    01e1ff20 79e77f9a 00000398 ffffffff 00000000 mscorwks!PEImage::LoadImage+0x199
    01e1ff70 79e77f50 ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
    01e1ff80 79f3549b ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17
    01e1ffa8 79f6ece3 00000000 b28c067c 01e1ffec mscorwks!SVR::gc_heap::gc_thread_function+0x2e
    01e1ffb8 77e66063 000e7660 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x9b
    01e1ffec 00000000 79f6ec79 000e7660 00000000 kernel32!BaseThreadStart+0x34

    上面的代码表明,GC正在等着干活……在我抓到的dump中,GC看起来这个样子:

    16  Id: f28.1150 Suspend: 1 Teb: fff82000 Unfrozen
    ChildEBP RetAddr  Args to Child             
    0248fd28 7d4d8c46 000002dc 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15
    0248fd98 79e77fd1 000002dc ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
    0248fddc 79e77f9a 000002dc ffffffff 00000000 mscorwks!PEImage::LoadImage+0x199
    0248fe2c 79e77f50 ffffffff 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
    0248fe3c 79f35e1a ffffffff 00000000 00000000 mscorwks!CLREvent::Wait+0x17
    0248fe54 7a0d5a3b 001afbf0 0000000d 00000002 mscorwks!SVR::t_join::join+0x61
    0248ff54 79f391bf 00000002 001afbf0 00000000 mscorwks!SVR::gc_heap::plan_phase+0xd78
    0248ff70 79f39954 00000002 ffffffff 001afbf0 mscorwks!SVR::gc_heap::gc1+0x57
    0248ff88 79f35422 00000000 00000000 001afbf0 mscorwks!SVR::gc_heap::garbage_collect+0x37c
    0248ffa8 79f6ece3 00000000 914b1904 0248ffec mscorwks!SVR::gc_heap::gc_thread_function+0x68
    0248ffb8 7d4e0729 001afbf0 00000000 00000000 mscorwks!SVR::gc_heap::gc_thread_stub+0x9b
    0248ffec 00000000 79f6ec79 001afbf0 00000000 kernel32!BaseThreadStart+0x34

    看上面的粗体,哦,正在Collect。就是说,我们闯到了GC的肚子里面。

    步骤2 - GC为什么开始工作了?

    先看一下,CPU都被谁用掉了?

    0:029> !runaway
     User Mode Time
      Thread       Time
     
     14:11b8      0 days 0:00:55.687
      16:1150      0 days 0:00:45.500
      17:7a8       0 days 0:00:43.875
      21:1244      0 days 0:00:23.140
     
      0:ea0       0 days 0:00:00.046
      29:fc8       0 days 0:00:00.000
      28:11f0      0 days 0:00:00.000

    0:021> .time
    Debug session time: Tue Jun 20 09:46:04.000 2006 (GMT+2)
    System Uptime: 4 days 6:36:51.031
    Process Uptime: 0 days 0:16:53.000
      Kernel time: 0 days 0:00:45.000
      User time: 0 days 0:02:48.000

    上面来看,大约有17分钟被程序用掉了。我们看一下14号在作什么?

      14  Id: f28.11b8 Suspend: 1 Teb: fff88000 Unfrozen
    ChildEBP RetAddr  Args to Child             
    020afc8c 7d4d8c46 00000224 00000000 020afcd0 ntdll!ZwWaitForSingleObject+0x15
    020afcfc 79e77fd1 00000224 00009c40 00000000 kernel32!WaitForSingleObjectEx+0xac
    020afd40 79e77f9a 00000224 00009c40 00000000 mscorwks!PEImage::LoadImage+0x199
    020afd90 79e77f50 00009c40 00000000 00000000 mscorwks!CLREvent::WaitEx+0x117
    020afda0 79f5b69c 00009c40 00000000 00000000 mscorwks!CLREvent::Wait+0x17
    020afe20 7a1121c3 001862f8 00009c40 00000000 mscorwks!ThreadpoolMgr::SafeWait+0x73
    020afe94 79f71123 00000000 00000000 00000000 mscorwks!ThreadpoolMgr::WorkerThreadStart+0xf1
    020affb8 7d4e0729 0019cab8 00000000 00000000 mscorwks!ThreadpoolMgr::intermediateThreadProc+0x49
    020affec 00000000 79f710dd 0019cab8 00000000 kernel32!BaseThreadStart+0x34

    哦,很清闲,什么都没干。但是,那17分钟中,有56秒在用着CPU,什么意思呢???我们继续看一下21号线程的托管堆。

    0:021> !clrstack
    OS Thread Id: 0x1244 (21)
    ESP       EIP    
    029ef1e8 7d61c824 [HelperMethodFrame: 029ef1e8]
    029ef254 02920df3 LargeObjectHeap.GetLotsOfDatesXML(Int32)
    029ef2a4 02920b20 LargeObjectHeap.Button1_Click(System.Object, System.EventArgs)
    029ef2b4 6881bdc6 System.Web.UI.WebControls.Button.OnClick(System.EventArgs)
    029ef2c8 6881bfbc System.Web.UI.WebControls.Button.RaisePostBackEvent(System.String)
    029ef2dc 6881bf38 System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(System.String)
    029ef2e0 687d91e0 System.Web.UI.Page.RaisePostBackEvent(System.Web.UI.IPostBackEventHandler, System.String)
    029ef2e8 687d912a System.Web.UI.Page.RaisePostBackEvent(System.Collections.Specialized.NameValueCollection)
    029ef2f8 687dcbbf System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
    029ef4b0 687db521 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
    029ef4e0 687db487 System.Web.UI.Page.ProcessRequest()
    029ef518 687db3a7 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
    029ef520 687db33a System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
    029ef534 02920795 ASP.largeobjectheap_aspx.ProcessRequest(System.Web.HttpContext)
    029ef538 686888df System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
    029ef56c 6865a071 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
    029ef5ac 6865a39b System.Web.HttpApplication.ResumeSteps(System.Exception)
    029ef5f4 6865912d System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
    029ef610 6865e0bd System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
    029ef644 6865dd72 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
    029ef650 6865c447 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
    029ef800 79f1ef33 [ContextTransitionFrame: 029ef800]
    029ef850 79f1ef33 [GCFrame: 029ef850]
    029ef9a8 79f1ef33 [ComMethodFrame: 029ef9a8]

    看上面的call stack,我们看到了LargeObjectHeap.GetLotsOfDatesXML(),这个咚咚触发了LOH的回收,然后按次序触发了2代、1代、0代。

    但是只有一个大对象,并不会导致高CPU的占用啊!那我们看一下实际的代码吧!

        String GetLotsOfDatesXML(int i)

        {

            String dates = "<Dates>";

            for (int j = 0; j < i; j++)

            {

                DateTime dt = DateTime.Now.Add(new TimeSpan(j, 0, 0, 0));

                dates += "<Date><Month>" + dt.Month + "</Month><Day>" + dt.Day + "</Day><DayOfWeek>" + dt.DayOfWeek + "</DayOfWeek><Date>";

                dates += "<Date><Month>" + dt.Month + "</Month><Day>" + dt.Day + "</Day><DayOfWeek>" + dt.DayOfWeek + "</DayOfWeek><Date>";

            }

            dates += "</Dates>";

            return dates;

        }

    如果外面传来的i小点还好,但是如果很大呢?对于确切地i是多少,我们需要一点一点地开始找。从callstack上面,我们看到是LargeObjectHeap.Button1_Click调用了GetLotsOfDatesXML方法。

        protected void Button1_Click(object sender, EventArgs e)

        {

            String str = GetLotsOfDatesXML(Int32.Parse(txtNumIterations.Text));

        }

    在这里,txtNumIterations是一个textbox控件。下面,基本上都是!do和!dso的工作了。

    0:021> !dso
    OS Thread Id: 0x1244 (21)
    ESP/REG  Object   Name
    029ef0f0 0b1a2270 System.String    <String is invalid or too large to print>
    029ef1a8 0b1a2270 System.String    <String is invalid or too large to print>
    029ef1bc 0b1a2270 System.String    <String is invalid or too large to print>
    029ef228 06a759e4 System.String    </DayOfWeek><Date>
    029ef28c 06a76df0 ASP.largeobjectheap_aspx
    029ef2b4 06a77b84 System.ComponentModel.EventHandlerList
    029ef2bc 06a77a84 System.Web.UI.WebControls.Button
    029ef2c8 06a76df0 ASP.largeobjectheap_aspx
    029ef304 06a76880 System.Web.HttpContext
    ...

    0:021> !do 06a76df0
    Name: ASP.largeobjectheap_aspx
    MethodTable: 02746ccc
    EEClass: 028d24cc
    Size: 380(0x17c) bytes
     (C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\Temporary ASP.NET Files\debuggersamples\e7443224\5232f845\App_Web_h0ctkxwz.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    790fa3e0  4001fe0        4        System.String  0 instance 02a7cba4 _id
    790fa3e0  4001fe1        8        System.String  0 instance 00000000 _cachedUniqueID
    68a2af44  4001fe2        c ...em.Web.UI.Control  0 instance 00000000 _parent
    68a91070  4001fe3       2c         System.Int32  0 instance        5 _controlState
    68a85ea0  4001fe4       10 ...m.Web.UI.StateBag  0 instance 00000000 _viewState
    68a2af44  4001fe5       14 ...em.Web.UI.Control  0 instance 00000000 _namingContainer
    68a273d0  4001fe6       18   System.Web.UI.Page  0 instance 06a76df0 _page
    ...
    68a7d910  4000004      16c ...ebControls.Button  0 instance 06a77a84 Button1
    68a95f40  4000005      170 ...bControls.TextBox  0 instance 06a77be4 txtNumIterations
    68a2bc80  4000006      174 ...Controls.HtmlForm  0 instance 06a77688 form1

    好,继续看一下这个textbox。

    0:021> !do 06a77be4
    Name: System.Web.UI.WebControls.TextBox
    MethodTable: 68a95f40
    EEClass: 68a95ebc
    Size: 80(0x50) bytes
     (C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    790fa3e0  4001fe0        4        System.String  0 instance 02a85a04 _id
    790fa3e0  4001fe1        8        System.String  0 instance 00000000 _cachedUniqueID
    68a2af44  4001fe2        c ...em.Web.UI.Control  0 instance 06a77688 _parent
    68a91070  4001fe3       2c         System.Int32  0 instance        5 _controlState
    68a85ea0  4001fe4       10 ...m.Web.UI.StateBag  0 instance 06a788f0 _viewState
    68a2af44  4001fe5       14 ...em.Web.UI.Control  0 instance 06a76df0 _namingContainer
    68a273d0  4001fe6       18   System.Web.UI.Page  0 instance 06a76df0 _page
    68a92e2c  4001fe7       1c ...+OccasionalFields  0 instance 06a78974 _occasionalFields
    68a2b378  4001fe8       20 ...I.TemplateControl  0 instance 00000000 _templateControl
    ...

    0:021> !do 06a788f0
    Name: System.Web.UI.StateBag
    MethodTable: 68a85ea0
    EEClass: 68a85e30
    Size: 16(0x10) bytes
     (C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    79113dfc  400235f        4 ...tions.IDictionary  0 instance 06a78900 bag
    79104f64  4002360        8       System.Boolean  0 instance        1 marked
    79104f64  4002361        9       System.Boolean  0 instance        0 ignoreCase

    0:021> !do 06a78900
    Name: System.Collections.Specialized.HybridDictionary
    MethodTable: 7a747ad4
    EEClass: 7a7aa890
    Size: 20(0x14) bytes
     (C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    7a747bac  4001145        4 ...ed.ListDictionary  0 instance 06a78924 list
    790fea70  4001146        8 ...ections.Hashtable  0 instance 00000000 hashtable
    79104f64  4001147        c       System.Boolean  0 instance        0 caseInsensitive

    0:021> !do 06a78924
    Name: System.Collections.Specialized.ListDictionary
    MethodTable: 7a747bac
    EEClass: 7a7aa918
    Size: 28(0x1c) bytes
     (C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    7a747c78  4001148        4 ...ry+DictionaryNode  0 instance 06a78940 head
    790fed1c  4001149       10         System.Int32  0 instance        1 version
    790fed1c  400114a       14         System.Int32  0 instance        1 count
    791117c8  400114b        8 ...ections.IComparer  0 instance 00000000 comparer
    790f9c18  400114c        c        System.Object  0 instance 00000000 _syncRoot

    0:021> !do 06a78940
    Name: System.Collections.Specialized.ListDictionary+DictionaryNode
    MethodTable: 7a747c78
    EEClass: 7a7aa9b8
    Size: 20(0x14) bytes
     (C:\WINDOWS\assembly\GAC_MSIL\System\2.0.0.0__b77a5c561934e089\System.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    790f9c18  4001158        4        System.Object  0 instance 06a66bd8 key
    790f9c18  4001159        8        System.Object  0 instance 06a78914 value
    7a747c78  400115a        c ...ry+DictionaryNode  0 instance 00000000 next

    0:021> !do 06a66bd8
    Name: System.String
    MethodTable: 790fa3e0
    EEClass: 790fa340
    Size: 26(0x1a) bytes
     (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
    String: Text
    ...

    找到了Text属性,看看是多少?

    0:021> !do 06a78914
    Name: System.Web.UI.StateItem
    MethodTable: 68a131b4
    EEClass: 68a13144
    Size: 16(0x10) bytes
     (C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    790f9c18  4002362        4        System.Object  0 instance 06a78184 value
    79104f64  4002363        8       System.Boolean  0 instance        1 isDirty

    0:021> !do 06a78184
    Name: System.String
    MethodTable: 790fa3e0
    EEClass: 790fa340
    Size: 28(0x1c) bytes
     (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
    String: 40000
    Fields:
          MT    Field   Offset                 Type VT     Attr    Value Name
    790fed1c  4000096        4         System.Int32  0 instance        6 m_arrayLength
    790fed1c  4000097        8         System.Int32  0 instance        5 m_stringLength
    790fbefc  4000098        c          System.Char  0 instance       34 m_firstChar
    790fa3e0  4000099       10        System.String  0   shared   static Empty
        >> Domain:Value  001a8868:790d6584 001ca990:790d6584 <<
    79124670  400009a       14        System.Char[]  0   shared   static WhitespaceChars
        >> Domain:Value  001a8868:06a303f0 001ca990:06a34118 <<


    靠,循环了4万次!

    结论:

    地球人都知道,用+=会产生3*n个对象,如果用StringBuilder,就不会有这个问题了。

  • 相关阅读:
    汉诺塔
    美丽联合2018前端
    游览器
    python多线程实现
    cuda toolkit
    编译器,解释器及混合编译
    大疆无人机
    SaaS PaaS IaaS mes
    CNN中权值共享的理解
    最近动作项目心得
  • 原文地址:https://www.cnblogs.com/liangqihui/p/972680.html
Copyright © 2011-2022 走看看