5.3.4　调整内存设置控制垃圾收集频率

三大块非用户程序时间中，还剩下GC时间没有调整，而GC时间却又是其中最重要的一块，并不只是因为它是耗时最长的一块，更因为它是一个稳定持续的过程。由于我们做的测试是在测程序的启动时间，所以类加载和编译时间在这项测试中的影响力被大幅度放大了。在绝大多数的应用中，不可能出现持续不断的类被加载和卸载。在程序运行一段时间后，热点方法被不断编译，新的热点方法数量也总会下降，但是垃圾收集则是随着程序运行而不断运作的，所以它对性能的影响才显得尤为重要。

在Eclipse启动的原始数据样本中，短短15秒，类共发生了19次Full GC和378次Minor GC，一共397次GC共造成了超过4秒的停顿，也就是超过1/4的时间都是在做垃圾收集，这个运行数据看起来实在太糟糕了。

首先来解决新生代中的Minor GC，虽然GC的总时间只有不到1秒，但却发生了378次之多。从VisualGC的线程监视中看到，Eclipse启动期间一共发起了超过70条线程，同时在运行的线程数超过25条，每当发生一次垃圾收集动作，所有用户线程^[1]都必须跑到最近的一个安全点（SafePoint）然后挂起线程等待垃圾回收。这样过于频繁的GC就会导致很多没有必要的安全点检测、线程挂起及恢复操作。

新生代GC频繁发生，很明显是由于虚拟机分配给新生代的空间太小而导致的，Eden区加上一个Survivor区还不到35MB。因此很有必要使用-Xmn参数调整新生代的大小。

再来看一看那19次Full GC，看起来19次并“不多”（相对于378次Minor GC来说），但总耗时为3.166秒，占了GC时间的绝大部分，降低GC时间的主要目标就要降低这部分时间。从VisualGC的曲线图上可能看得不够精确，这次直接从GC日志^[2]中分析一下这些Full GC是如何产生的，代码清单5-9中是启动最开始的2.5秒内发生的10次Full GC记录。

代码清单5-9　Full GC记录

0.278：[GC 0.278：[DefNew：574K-＞33K（576K），0.0012562 secs]0.279：[Tenured：1467K-＞997K（1536K），0.0181775 secs]1920K-＞997K（2112K），0.0195257 secs]

0.312：[GC 0.312：[DefNew：575K-＞64K（576K），0.0004974 secs]0.312：[Tenured：1544K-＞1608K（1664K），0.0191592 secs]1980K-＞1608K（2240K），0.0197396 secs]

0.590：[GC 0.590：[DefNew：576K-＞64K（576K），0.0006360 secs]0.590：[Tenured：2675K-＞2219K（2684K），0.0256020 secs]3090K-＞2219K（3260K），0.0263501 secs]

0.958：[GC 0.958：[DefNew：551K-＞64K（576K），0.0011433 secs]0.959：[Tenured：3979K-＞3470K（4084K），0.0419335 secs]4222K-＞3470K（4660K），0.0431992 secs]

1.575：[Full GC 1.575：[Tenured：4800K-＞5046K（5784K），0.0543136 secs]5189K-＞5046K（6360K），[Perm：12287K-＞12287K（12288K）]，0.0544163 secs]

1.703：[GC 1.703：[DefNew：703K-＞63K（704K），0.0012609 secs]1.705：[Tenured：8441K-＞8505K（8540K），0.0607638 secs]8691K-＞8505K（9244K），0.0621470 secs]

1.837：[GC 1.837：[DefNew：1151K-＞64K（1152K），0.0020698 secs]1.839：[Tenured：14616K-＞14680K（14688K），0.0708748 secs]15035K-＞14680K（15840K），0.0730947 secs]

2.144：[GC 2.144：[DefNew：1856K-＞191K（1856K），0.0026810 secs]2.147：[Tenured：25092K-＞24656K（25108K），0.1112429 secs]26172K-＞24656K（26964K），0.1141099 secs]

2.337：[GC 2.337：[DefNew：1914K-＞0K（3136K），0.0009697 secs]2.338：[Tenured：41779K-＞27347K（42056K），0.0954341 secs]42733K-＞27347K（45192K），0.0965513 secs]

2.465：[GC 2.465：[DefNew：2490K-＞0K（3456K），0.0011044 secs]2.466：[Tenured：46379K-＞27635K（46828K），0.0956937 secs]47621K-＞27635K（50284K），0.0969918 secs]

括号中加粗的数字代表老年代的容量，这组GC日志显示了10次Full GC发生的原因全部都是老年代空间耗尽，每发生一次Full GC都伴随着一次老年代空间扩容：1536KB-＞1664KB-＞2684KB……42056KB-＞46828KB，10次GC以后老年代容量从起始的1536KB扩大到46828KB，当15秒后Eclipse启动完成时，老年代容量扩大到了103428KB，代码编译开始后，老年代容量到达顶峰473MB，整个Java堆到达最大容量512MB。

日志还显示有些时候内存回收状况很不理想，空间扩容成为获取可用内存的最主要手段，譬如语句“Tenured：25092K-＞24656K（25108K），0.1112429 secs”，代表老年代当前容量为25108KB，内存使用到25092KB的时候发生Full GC，花费0.11秒把内存使用降低到24656KB，只回收了不到500KB的内存，这次GC基本没有什么回收效果，仅仅做了扩容，扩容过程相比起回收过程可以看做是基本不需要花费时间的，所以说这0.11秒几乎是白白浪费了。

由上述分析可以得出结论：Eclipse启动时，Full GC大多数是由于老年代容量扩展而导致的，由永久代空间扩展而导致的也有一部分。为了避免这些扩展所带来的性能浪费，我们可以把-Xms和-XX：PermSize参数值设置为-Xmx和-XX：MaxPermSize参数值一样，这样就强制虚拟机在启动的时候就把老年代和永久代的容量固定下来，避免运行时自动扩展^[3]。

根据分析，优化计划确定为：把新生代容量提升到128MB，避免新生代频繁GC；把Java堆、永久代的容量分别固定为512MB和96MB^[4]，避免内存扩展。这几个数值都是根据机器硬件、Eclipse插件和工程数量来决定的，读者实践的时候应根据VisualGC中收集到的实际数据进行设置。改动后的eclipse.ini配置如代码清单5-10所示。

代码清单5-10　内存调整后的Eclipse配置文件

-vm

D：/_DevSpace/jdk1.6.0_21/bin/javaw.exe

-startup

plugins/org.eclipse.equinox.launcher_1.0.201.R35x_v20090715.jar

—launcher.library

plugins/org.eclipse.equinox.launcher.win32.win32.x86_1.0.200.v20090519

-product

org.eclipse.epp.package.jee.product

-showsplash

org.eclipse.platform

-vmargs

-Dosgi.requiredJavaVersion=1.5

-Xverify：none

-Xmx512m

-Xms512m

-Xmn128m

-XX：PermSize=96m

-XX：MaxPermSize=96m

现在这个配置之下，GC次数已经大幅度降低，图5-9是Eclipse启动后1分钟的监视曲线，只发生了8次Minor GC和4次Full GC，总耗时为1.928秒。

图　5-9　GC调整后的运行数据

这个结果已经算是基本正常，但是还存在一点瑕疵：从Old Gen的曲线上看，老年代直接固定在384MB，而内存使用量只有66MB，并且一直很平滑，完全不应该发生Full GC才对，那4次Full GC是怎么来的？使用jstat-gccause查询一下最近一次GC的原因，见代码清单5-11。

代码清单5-11　查询GC原因

C：\Users\IcyFenix＞jps

9772 Jps

4068 org.eclipse.equinox.launcher_1.0.201.R35x_v20090715.jar

C：\Users\IcyFenix＞jstat-gccause 4068

S0 S1 E O P YGC YGCT FGC FGCT GCT LGCC GCC

0.00 0.00 1.00 14.81 39.29 6 0.422 20 5.992 6.414

System.gc（）No GC

从LGCC（Last GC Cause）中看到，原来是代码调用System.gc（）显式触发的GC，在内存设置调整后，这种显式GC已不符合我们的期望，因此在eclipse.ini中加入参数-XX：+DisableExplicitGC屏蔽掉System.gc（）。再次测试发现启动期间的Full GC已经完全没有了，只有6次Minor GC，耗时417毫秒，与调优前4.149秒的测试样本相比，正好是十分之一。进行GC调优后Eclipse的启动时间下降非常明显，比整个GC时间降低的绝对值还大，现在启动只需要7秒多，如图5-10所示。

图　5-10　Eclipse启动时间

[1]严格来说，不包括正在执行native代码的用户线程，因为native代码一般不会改变Java对象的引用关系，所以没有必要挂起它们来等待垃圾回收。

[2]可以通过以下几个参数要求虚拟机生成GC日志：-XX：+PrintGCTimeStamps（打印GC停顿时间）、-XX：+PrintGCDetails（打印GC详细信息）、-verbose：gc（打印GC信息，输出内容已被前一个参数包括，可以不写）、-Xloggc：gc.log。

[3]需要说明一点，虚拟机启动的时候就会把参数中所设定的内存全部划为私有，即使扩容前有一部分内存不会被用户代码用到，这部分内存也不会交给其他进程使用。这部分内存在虚拟机中被标识为“Virtual”内存。

[4]512MB和96MB两个数值对于笔者的应用情况来说依然偏少，但由于笔者需要同时开启VMWare工作，所以需要预留较多内存，读者在实际调优时不妨再设置大一些。