（转） High CPU in GC
问题描述：
程序慢的要死，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，就不会有这个问题了。
