分析性能瓶頸: 調試OutOfMemoryException

在前面的文章裡面，執行性能測試—起步裡，講了執行性能測試的基本步驟，而且在前面的 例子裡面，通過一個2M多的文本文件，對比了冒泡排序和快速排序的性能之間的差別。但是當 我使用一個700M大小的文本文件進行測試的時候—因為我需要了解在極端情況下兩種排序方法 的差別。原定是2G的文本文件，但是無論快排還是冒泡排序都要求被排序的數據完全存在於內 存當中，對於32位機，2G的數據是一個上限，因為操作系統的內核代碼使用掉了另外2G的地址 空間—除非你使用/LARGEADDRESSAWARE這個開關，限制操作系統只使用1G的內存，而讓用戶態 代碼使用3G的空間。

為了重現這個問題，我們先來准備一下數據，用下面兩個DOS命令就可以准備好這些數據了 ：

1.dir /s /b c:\windows > d:\test.txt

2.FOR /L %i IN (1,1,100) DO type test.txt >> testdata.txt

第一個命令將Windows文件夾裡面所有子文件夾的文件列表都輸出到test.txt文件裡，第二 個命令循環100遍，將test.txt文件內容追加到testdata.txt裡面，這樣就可以生成好幾百兆大 小的文本文件了。

數據生成好了以後，使用執行性能測試—起步貼出來的程序執行一遍，就可以看到 OutOfMemeoryException了（如果你沒有看到這個異常，可能是你的機器太強大了，請換一個更 大的文件）。在調試器裡面執行後出現異常後，加載進SOS進行分析：

　(318.1688):　CLR　exception　-　code　e0434352　(first　chance)
…　…
#
#　OutOfMemeoryException已經拋出了
#
　 (318.1688):　CLR　exception　-　code　e0434352　(!!!　second　chance　!!!)
eax=0017eb74　ebx=00000005　ecx=00000005　edx=00000000　esi=0017ec20　 edi=005595e0
eip=753b9617　esp=0017eb74　ebp=0017ebc4　iopl=0　　　　　　　　　nv　up　ei　pl 　nz　ac　pe　nc
cs=001b　ss=0023　ds=0023　es=0023　fs=003b　gs=0000　　　　　　　　　　　　　 efl=00000216
KERNELBASE!RaiseException+0x54:
753b9617　c9　　　　　　　　　　　　　　leave
0:000>　.loadby　sos　clr
0:000>　!pe
Exception　object:　744a8e84
Exception　type:　　　System.OutOfMemoryException
Message:　　　　　　　　　　<none>
InnerException:　　　<none>
StackTrace　(generated):
SP　　　　　　　IP　　　　　　　Function
#
#　不出所料，StreamReader裡面使用StringBuilder將文本文件讀入到一個字符串裡。而 StringBuilder是動態
#　分配內存的。
#
　　　　 0017ED38　5713E61E　mscorlib_ni!System.Text.StringBuilder.ToString() +0x1e
　　　　 0017ED64　57121991　mscorlib_ni!System.IO.StreamReader.ReadToEnd() +0x7d
　　　　 0017ED78　002F0136　ConsoleApplication1! ConsoleApplication1.Program.Main(System.String[])+0xc6

StackTraceString:　<none>
HResult:　8007000e
#
#　使用AnalyzeOOM來分析一下原因，看看是GC哪一個內存區域導致了這個異常。
#
0:000>　!ao
#
#　找到了，是大對象堆（Large　Object　Heap　-　LOH），GC在嘗試申請一個1.5G的內存 空間時
#　遭拒。
#
Managed　OOM　occured　after　GC　#312　(Requested　to　allocate　1649667816　 bytes)
Reason:　Didn't　have　enough　memory　to　allocate　an　LOH　segment
Detail:　LOH:　Failed　to　reserve　memory　(1652555776　bytes)
#
#　使用!eeheap　–gc命令找到GC裡，各個generation的堆的起始地址和結束地址
#
0:000>　!eeheap　-gc
Number　of　GC　Heaps:　1
generation　0　starts　at　0x744a8e78
generation　1　starts　at　0x7446a408
generation　2　starts　at　0x01911000
ephemeral　segment　allocation　context:　none
　 segment　　　　　begin　allocated　size
01910000　01911000　0290aee0　0xff9ee0(16752352)
03fd0000　03fd1000　04fcd3ec　0xffc3ec(16761836)
…　…
73ca0000　73ca1000　744aae84　0x809e84(8429188)
Large　object　heap　starts　at　0x02911000
#
#　LOH的起始地址找到了，0x02911000就是LOH的起始地址
#　已經分配了0x02913240個字節，所以結束地址就是
#　0x02911000　+　0x02913240
#
　 segment　　　　　begin　allocated　size
02910000　02911000　02913240　0x2240(8768)
Total　Size:　　　　　　　　　　　　　　Size:　0x629424c0　(1653875904)　 bytes.
------------------------------
GC　Heap　Size:　　　　　　　　　　　　Size:　0x629424c0　(1653875904)　 bytes.
#
#　使用dumpheap看一下LOH當中各個對象的內存分配情況。
#
#　dumpheap的參數中，0x02911000是要查看的內存的起始地址，
#　而0x02911000　+　0x02913240是查看的結束地址
#
0:000>　!dumpheap　-stat　02911000　02911000+02913240
total　0　objects
Statistics:
　　　　　　 MT　　　　Count　　　　TotalSize　Class　Name
00529748　　　　　　　　4　　　　　　　　　　　84　　　　　　Free
57166c28　　　　　　　　3　　　　　　　　　8720　System.Object[]
#
#　不出所料，StringBuilder和Char[]對象最多，但是
#　Char[]的數組大小有171M之多。
#
571afb78　　　　　1119　　　　　　　　31332　System.Text.StringBuilder
571b1d88　　　　　1120　　　　　17933440　System.Char[]
Total　2246　objects
#
#　使用!dumpheap的-mt參數看看char[]數組的詳細內存分配情況
#　
#　571b1d88這個參數，來自於前面的!dumpheap命令的輸出（注意高亮顯示的地方）
#　這個參數告訴dumpheap命令，只檢索char[]數組（Method　table是571b1d88）
#　的情況。
#
0:000>　!dumpheap　-mt　571b1d88　02911000　02911000+02913240
　 Address　　　　　　　MT　　　　　Size
03fd1000　571b1d88　　　　16012
…　…
05222c90　571b1d88　　　　16012
total　0　objects
Statistics:
　　　　　　 MT　　　　Count　　　　TotalSize　Class　Name
571b1d88　　　　　1120　　　　　17933440　System.Char[]
Total　1120　objects
#
#　隨便選一個對象（注意上面一個高亮顯示的文本），看看它到底被誰引用了，
#　導致GC一直不釋放它，畢竟我電腦的有2G的物理內存，讀取幾百兆的文件，
#　就觸發了OutOfMemoryException，的確有點離譜。
#
0:000>　!gcroot　03fd1000
Note:　Roots　found　on　stacks　may　be　false　positives.Run　"!help　gcroot"　 for
more　info.
Scan　Thread　0　OSTHread　1688
ESP:17eca4:Root:　0191d2e0(System.Text.StringBuilder)->
　 744a4fd0(System.Text.StringBuilder)->
　 …　…
　 5de44814(System.Text.StringBuilder)->
Command　cancelled　at　the　user's　request.
　 03fd1000(System.Char[])
#
#　再看看0x0191d2e0這個StringBuilder對象都在哪些地方被引用到了，
#　根據GC的實現，堆棧上各個函數的局部變量是當作root來處理的
#
0:000>　!gcroot　0191d2e0
Note:　Roots　found　on　stacks　may　be　false　positives.Run　"!help　gcroot"　 for
more　info.
Scan　Thread　0　OSTHread　1688
ESP:17eca4:Root:　0191d2e0(System.Text.StringBuilder)
ESP:17eca8:Root:　0191d2e0(System.Text.StringBuilder)
ESP:17ecb4:Root:　0191d2e0(System.Text.StringBuilder)
ESP:17ecbc:Root:　0191d2e0(System.Text.StringBuilder)
ESP:17ed3c:Root:　0191d2e0(System.Text.StringBuilder)
ESP:17ed58:Root:　0191d2e0(System.Text.StringBuilder)
Scan　Thread　2　OSTHread　ce8
#
#　從前面的輸出，隨便找兩個對象（前面標注的文本）,看看它們都是哪些函數的局部變量
#　例如17ed58這個地址介於System.IO.StreamReader.ReadToEnd()和
#　System.Text.StringBuilder.ToString()之間，也就是StreamReader.ReadToEnd()
#　這個函數定義的，至此，基本上我們可以認為已經找到影響性能的元凶了。
#
0:000>　!dumpstack
OS　Thread　Id:　0x1688　(0)
Current　frame:　KERNELBASE!RaiseException+0x54
ChildEBP　RetAddr　Caller,　Callee
0017eb7c　753b9617　KERNELBASE!RaiseException+0x54,　calling　ntdll! RtlRaiseException
0017eba0　5888bc5e　clr!DllUnregisterServerInternal+0x15c62,　calling　clr! DllUnregisterServerInternal+0xa55b
0017ebac　588fa99c　clr!LogHelp_TerminateOnAssert+0x2df44,　calling　clr! DllUnregisterServerInternal+0x15c45
0017ebbc　58871bd0　clr+0x1bd0,　calling　clr+0x1b8b
0017ebc4　588fac08　clr!LogHelp_TerminateOnAssert+0x2e1b0,　calling　KERNEL32! RaiseException
0017ec54　5896ab0b　clr!CopyPDBs+0x4abd,　calling　clr! LogHelp_TerminateOnAssert+0x2e03e
0017ec90　58b27c9e　clr!CorLaunchApplication+0x11756,　calling　clr! CopyPDBs+0x4a78
0017ecdc　588908f6　clr!CoUninitializeEE+0x272e,　calling　clr! GetMetaDataInternalInterface+0xde18
0017ed30　5713e61e　(MethodDesc　56f0c09c　+0x1e　 System.Text.StringBuilder.ToString()),　calling　00242350
0017ed5c　57121991　(MethodDesc　56efff40　+0x7d　 System.IO.StreamReader.ReadToEnd())
0017ed70　002f0136　(MethodDesc　00253840　+0xc6　 ConsoleApplication1.Program.Main(System.String[]))
0017edd4　588721db　clr+0x21db
0017ede4　58894a2a　clr!CoUninitializeEE+0x6862,　calling　clr+0x21a8
…　…
0017f91c　589daf00　clr!CorExeMain+0x1c,　calling　clr!GetCLRFunction+0xd6a
0017f954　718455ab　mscoreei!CorExeMain+0x38
0017f960　6f667f16　MSCOREE!CreateConfigStream+0x13f
0017f970　6f664de3　MSCOREE!CorExeMain+0x8,　calling　MSCOREE! CorExeMain+0x2f14
0017f978　75d41194　KERNEL32!BaseThreadInitThunk+0x12
0017f984　7723b495　ntdll!RtlInitializeExceptionChain+0x63
0017f9c4　7723b468　ntdll!RtlInitializeExceptionChain+0x36,　calling　ntdll! RtlInitializeExceptionChain+0x3c