分析性能瓶颈 — 调试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