- 前言
- 第2版与第1版的区别
- 本书面向的读者
- 如何阅读本书
- 语言约定
- 内容特色
- 参考资料
- 第一部分 走近 Java
- 第1章 走近 Java
- 第二部分 自动内存管理机制
- 第2章 Java 内存区域与内存溢出异常
- 第3章 垃圾收集器与内存分配策略
- 第4章 虚拟机性能监控与故障处理工具
- 第5章 调优案例分析与实战
- 第三部分 虚拟机执行子系统
- 第6章 类文件结构
- 第7章 虚拟机类加载机制
- 第8章 虚拟机字节码执行引擎
- 第9章 类加载及执行子系统的案例与实战
- 第四部分 程序编译与代码优化
- 第10章 早期(编译期)优化
- 第11章 晚期(运行期)优化
- 第五部分 高效并发
- 第12章 Java 内存模型与线程
- 第13章 线程安全与锁优化
- 附录
- 附录A 编译 Windows 版的 OpenJDK
- 附录B 虚拟机字节码指令表
- 附录C HotSpot 虚拟机主要参数表
- 附录D 对象查询语言(OQL)简介[1]
- 附录E JDK 历史版本轨迹
5.3 实战:Eclipse 运行速度调优
很多Java开发人员都有这样一种观念:系统调优的工作都是针对服务端应用而言,规模越大的系统,就越需要专业的调优运维团队参与。这个观点不能说不对,5.2节中笔者所列举的案例确实都是服务端运维、调优的例子,但服务端应用需要调优,并不说明其他应用就不需要了,作为一个普通的Java开发人员,前面讲的各种虚拟机的原理和最佳实践方法距离我们并不遥远,开发者身边很多场景都可以使用上面这些知识。下面通过一个普通程序员日常工作中可以随时接触到的开发工具开始这次实战。
5.3.1 调优前的程序运行状态
笔者使用Eclipse作为日常工作中的主要IDE工具,由于安装的插件比较大(如Klocwork、ClearCase LT等)、代码也很多,启动Eclipse直到所有项目编译完成需要四五分钟。一直对开发环境的速度感觉不满意,趁着编写这本书的机会,决定对Eclipse进行“动刀”调优。
笔者机器的Eclipse运行平台是32位Windows 7系统,虚拟机为HotSpot VM 1.5 b64。硬件为ThinkPad X201,Intel i5 CPU,4GB物理内存。在初始的配置文件eclipse.ini中,除了指定JDK的路径、设置最大堆为512MB以及开启了JMX管理(需要在VisualVM中收集原始数据)外,未做其他任何改动,原始配置内容如代码清单5-3所示。
代码清单5-3 Eclipse 3.5初始配置
-vm D:/_DevSpace/jdk1.5.0/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 --launcher.XXMaxPermSize 256M -showsplash org.eclipse.platform -vmargs -Dosgi.requiredJavaVersion=1.5 -Xmx512m -Dcom.sun.management.jmxremote
为了要与调优后的结果进行量化对比,调优开始前笔者先做了一次初始数据测试。测试用例很简单,就是收集从Eclipse启动开始,直到所有插件加载完成为止的总耗时以及运行状态数据,虚拟机的运行数据通过VisualVM及其扩展插件VisualGC进行采集。测试过程中反复启动数次Eclipse直到测试结果稳定后,取最后一次运行的结果作为数据样本(为了避免操作系统未能及时进行磁盘缓存而产生的影响),数据样本如图5-2所示。
图 5-2 Eclipse原始运行数据
Eclipse启动的总耗时没有办法从监控工具中直接获得,因为VisualVM不可能知道Eclipse运行到什么阶段算是启动完成。为了测试的准确性,笔者写了一个简单的Eclipse插件,用于统计Eclipse的启动耗时。由于代码很简单,并且本书不是Eclipse RCP开发的教程,所以只列出代码清单5-4供读者参考,不再延伸讲解。如果读者需要这个插件,可以使用下面代码自行编译或者发电子邮件向笔者索取。
代码清单5-4 Eclipse启动耗时统计插件
ShowTime.java代码: import org.eclipse.jface.dialogs.MessageDialog; import org.eclipse.swt.widgets.Display; import org.eclipse.swt.widgets.Shell; import org.eclipse.ui.IStartup; /** *统计Eclipse启动耗时 *@author zzm */ public class ShowTime implements IStartup{ public void earlyStartup(){ Display.getDefault().syncExec(new Runnable(){ public void run(){ long eclipseStartTime=Long.parseLong(System.getProperty("eclipse.startTime")); long costTime=System.currentTimeMillis()-eclipseStartTime; Shell shell=Display.getDefault().getActiveShell(); String message="Eclipse启动耗时:"+costTime+"ms"; MessageDialog.openInformation(shell,"Information",message); } }); } } plugin.xml代码: <?xml version="1.0"encoding="UTF-8"?> <?eclipse version="3.4"?> <plugin> <extension point="org.eclipse.ui.startup"> <startup class="eclipsestarttime.actions.ShowTime"/> </extension> </plugin>
上述代码打包成jar后放到Eclipse的plugins目录,反复启动几次后,插件显示的平均时间稳定在15秒左右,如图5-3所示。
图 5-3 耗时统计插件运行效果
根据VisualGC和Eclipse插件收集到的信息,总结原始配置下的测试结果如下。
整个启动过程平均耗时约15秒。
最后一次启动的数据样本中,垃圾收集总耗时4.149秒,其中:
●Full GC被触发了19次,共耗时3.166秒。
●Minor GC被触发了378次,共耗时0.983秒。
加载类9115个,耗时4.114秒。
JIT编译时间为1.999秒。
虚拟机512MB的堆内存被分配为40MB的新生代(31.5的Eden空间和两个4MB的Surviver空间)以及472MB的老年代。
客观地说,由于机器硬件还不错(请读者以2010年普通PC机的标准来衡量),15秒的启动时间其实还在可接受范围以内,但是从VisualGC中反映的数据来看,主要问题是非用户程序时间(图5-2中的Compile Time、Class Load Time、GC Time)非常之高,占了整个启动过程耗时的一半以上(这里存在少许夸张成分,因为如JIT编译等动作是在后台线程完成的,用户程序在此期间也正常执行,所以并没有占用了一半以上的绝对时间)。虚拟机后台占用太多时间也直接导致Eclipse在启动后的使用过程中经常有不时停顿的感觉,所以进行调优有较大的价值。
5.3.2 升级JDK 1.6的性能变化及兼容问题
对Eclipse进行调优的第一步就是先把虚拟机的版本进行升级,希望能先从虚拟机版本身上得到一些“免费的”性能提升。
每次JDK的大版本发布时,开发商肯定都会宣称虚拟机的运行速度比上一版本有了很大的提高,这虽然是个广告性质的宣言,经常被人从升级列表或者技术白皮书中直接忽略过去,但从国内外的第三方评测数据来看,版本升级至少某些方面确实带来了一定的性能改善[1],以下是一个第三方网站对JDK 1.5、1.6、1.7三个版本做的性能评测,分别测试了以下4个用例[2]:
生成500万个的字符串。
500万次ArrayList<String>数据插入,使用第一点生成的数据。
生成500万个HashMap<String,Integer>,每个键-值对通过并发线程计算,测试并发能力。
打印500万个ArrayList<String>中的值到文件,并重读回内存。
三个版本的JDK分别运行这3个用例的测试程序,测试结果如图5-4所示。
图 5-4 JDK横向性能对比
从这4个用例的测试结果来看,JDK 1.6比JDK 1.5有大约15%的性能提升,尽管对JDK仅测试这4个用例并不能说明什么问题,需要通过测试数据来量化描述一个JDK比旧版提升了多少是很难做到非常科学和准确的(要做稍微靠谱一点的测试,可以使用SPECjvm2008[3]来完成,或者把相应版本的TCK[4]中数万个测试用例的性能数据对比一下可能更有说服力),但我还是选择相信这次“软广告”性质的测试,把JDK版本升级到1.6 Update 21。
与所有小说作者设计的故事情节一样,获得最后的胜利之前总是要经历各种各样的挫折,这次升级到JDK 1.6之后,性能有什么变化先暂且不谈,在使用几分钟之后,笔者的Eclipse就和前面几个服务端的案例一样非常“不负众望”地发生了内存溢出,如图5-5所示。
图 5-5 Eclipse OutOfMemoryError
这次内存溢出完全出乎笔者的意料之外:决定对Eclipse做调优是因为速度慢,但开发环境一直都很稳定,至少没有出现过内存溢出的问题,而这次升级除了eclipse.ini中的JVM路径改变了之外,还未进行任何运行参数的调整,进到Eclipse主界面之后随便打开了几个文件就抛出内存溢出异常了,难道JDK 1.6 Update 21有哪个API出现了严重的泄漏问题吗?
事实上,并不是JDK 1.6出现了什么问题,根据前面章节中介绍的相关原理和工具,我们要查明这个异常的原因并且解决它一点也不困难。打开VisualVM,监视页签中的内存曲线部分如图5-6和图5-7所示。
图 5-6 Java堆监视曲线
图 5-7 永久代监视曲线
在Java堆中监视曲线中,“堆大小”的曲线与“使用的堆”的曲线一直都有很大的间隔距离,每当两条曲线开始有互相靠近的趋势时,“最大堆”的曲线就会快速向上转向,而“使用的堆”的曲线会向下转向。“最大堆”的曲线向上是虚拟机内部在进行堆扩容,运行参数中并没有指定最小堆(-Xms)的值与最大堆(-Xmx)相等,所以堆容量一开始并没有扩展到最大值,而是根据使用情况进行伸缩扩展。“使用的堆”的曲线向下是因为虚拟机内部触发了一次垃圾收集,一些废弃对象的空间被回收后,内存用量相应减少,从图形上看,Java堆运作是完全正常的。但永久代的监视曲线就有问题了,“PermGen大小”的曲线与“使用的PermGen”的曲线几乎完全重合在一起,这说明永久代中没有可回收的资源,所以“使用的PermGen”的曲线不会向下发展,永久代中也没有空间可以扩展,所以“PermGen大小”的曲线不能向上扩展。这次内存溢出很明显是永久代导致的内存溢出。
再注意到图5-7中永久代的最大容量:“67,108,864个字节”,也就是64MB,这恰好是JDK在未使用-XX:MaxPermSize参数明确指定永久代最大容量时的默认值,无论JDK 1.5还是JDK 1.6,这个默认值都是64MB。对于Eclipse这种规模的Java程序来说,64MB的永久代内存空间显然是不够的,溢出很正常,那为何在JDK 1.5中没有发生过溢出呢?
在VisualVM的“概述-JVM参数”页签中,分别检查使用JDK 1.5和JDK 1.6运行Eclipse时的JVM参数,发现使用JDK 1.6时,只有以下3个JVM参数,如代码清单5-5所示。
代码清单5-5 JDK 1.6的Eclipse运行期参数
-Dcom.sun.management.jmxremote -Dosgi.requiredJavaVersion=1.5 -Xmx512m
而使用JDK 1.5运行时,就有4条JVM参数,其中多出来的一条正好就是设置永久代最大容量的-XX:MaxPermSize=256M,如代码清单5-6所示。
代码清单5-6 JDK 1.5的Eclipse运行期参数
-Dcom.sun.management.jmxremote -Dosgi.requiredJavaVersion=1.5 -Xmx512m -XX:MaxPermSize=256M
为什么会这样呢?笔者从Eclipse的Bug List网站[5]上找到了答案:使用JDK 1.5时之所以有永久代容量这个参数,是因为在eclipse.ini中存在“--launcher.XXMaxPermSize 256M”这项设置,当launcher——也就是Windows下的可执行程序eclipse.exe,检测到假如是Eclipse运行在Sun公司的虚拟机上的话,就会把参数值转化为-XX:MaxPermSize传递给虚拟机进程,因为三大商用虚拟机中只有Sun系列的虚拟机才有永久代的概念,也就是只有HotSpot虚拟机需要设置这个参数,JRockit虚拟机和IBM J9虚拟机都不需要设置。
在2009年4月20日,Oracle公司正式完成了对Sun公司的收购,此后无论是网页还是具体程序产品,提供商都从Sun变为了Oracle,而eclipse.exe就是根据程序提供商判断是否为Sun的虚拟机,当JDK 1.6 Update 21中java.exe、javaw.exe的“Company”属性从“Sun Microsystems Inc.”变为“Oracle Corporation”之后,Eclipse就完全不认识这个虚拟机了,因此没有把最大永久代的参数传递过去。
了解原因之后,解决方法就简单了,launcher不认识就只好由人来告诉它,即在eclipse.ini中明确指定-XX:MaxPermSize=256M这个参数就可以了。
[1]版本升级也有不少性能倒退的案例,受程序、第三方包兼容性以及中间件限制,在企业应用中升级JDK版本是一件需要慎重考虑的事情。
[2]测试用例、数据及图片来自:http://geeknizer.com/java-7-whats-new-performance-benchmark-1-5-1-6-1-7
[3]官方网站:http://www.spec.org/jvm2008/docs/UserGuide.html。
[4]TCK(Technology Compatibility Kit)是一套由一组测试用例和相应的测试工具组成的工具包,用于保证一个使用Java技术的实现能够完全遵守其适用的Java平台规范,并且符合相应的参考实现。
[5]https://bugs.eclipse.org/bugs/show_bug.cgi?id=319514。
5.3.3 编译时间和类加载时间的优化
从Eclipse启动时间上来看,升级到JDK 1.6所带来的性能提升是……嗯?基本上没有提升?多次测试的平均值与JDK 1.5的差距完全在实验误差范围之内。
各位读者不必失望,Sun JDK 1.6性能白皮书[1]描述的众多相对于JDK 1.5的提升不至于全部是广告,虽然总启动时间没有减少,但在查看运行细节的时候,却发现了一件很值得注意的事情:在JDK 1.6中启动完Eclipse所消耗的类加载时间比JDK 1.5长了接近一倍,不要看反了,这里写的是JDK 1.6的类加载比JDK 1.5慢一倍,测试结果如代码清单5-7所示,反复测试多次仍然是相似的结果。
代码清单5-7 JDK 1.5和JDK 1.6中的类加载时间对比
使用JDK 1.6的类加载时间: C:\Users\IcyFenix>jps 3552 6372 org.eclipse.equinox.launcher_1.0.201.R35x_v20090715.jar 6900 Jps C:\Users\IcyFenix>jstat-class 6372 Loaded Bytes Unloaded Bytes Time 7917 10190.3 0 0.0 8.18 使用JDK 1.5的类加载时间: C:\Users\IcyFenix>jps 3552 7272 Jps 7216 org.eclipse.equinox.launcher_1.0.201.R35x_v20090715.jar C:\Users\IcyFenix>jstat-class 7216 Loaded Bytes Unloaded Bytes Time 7902 9691.2 3 2.6 4.34
在本例中,类加载时间上的差距并不能作为一个具有普遍性的测试结果去说明JDK 1.6的类加载必然比JDK 1.5慢,笔者测试了自己机器上的Tomcat和GlassFish启动过程,并未没有出现类似的差距。在国内最大的Java社区中,笔者发起过关于此问题的讨论[2],从参与者反馈的测试结果来看,此问题只在一部分机器上存在,而且JDK 1.6的各个Update版之间也存在很大差异。
多次试验后,笔者发现在机器上两个JDK进行类加载时,字节码验证部分耗时差距尤其严重。考虑到实际情况:Eclipse使用者甚多,它的编译代码我们可以认为是可靠的,不需要在加载的时候再进行字节码验证,因此通过参数-Xverify:none禁止掉字节码验证过程也可作为一项优化措施。加入这个参数后,两个版本的JDK类加载速度都有所提高,JDK 1.6的类加载速度仍然比JDK 1.5慢,但是两者的耗时已经接近了许多,测试数据如代码清单5-8所示。关于类与类加载的话题,譬如刚刚提到的字节码验证是怎么回事,本书专门规划了两个章节进行详细讲解,在此不再延伸讨论。
代码清单5-8 JDK 1.5和JDK 1.6中取消字节码验证后的类加载时间对比
使用JDK 1.6的类加载时间: C:\Users\IcyFenix>jps 5512 org.eclipse.equinox.launcher_1.0.201.R35x_v20090715.jar 5596 Jps C:\Users\IcyFenix>jstat-class 5512 Loaded Bytes Unloaded Bytes Time 6749 8837.0 0 0.0 3.94 使用JDK 1.5的类加载时间: C:\Users\IcyFenix>jps 4724 org.eclipse.equinox.launcher_1.0.201.R35x_v20090715.jar 5412 Jps C:\Users\IcyFenix>jstat-class 4724 Loaded Bytes Unloaded Bytes Time 6885 9109.7 3 2.6 3.10
在取消字节码验证之后,JDK 1.5的平均启动下降到了13秒,而JDK 1.6的测试数据平均比JDK 1.5快1秒,下降到平均12秒左右,如图5-8所示。在类加载时间仍然落后的情况下,依然可以看到JDK 1.6在性能上比JDK 1.5稍有优势,说明至少在Eclipse启动这个测试用例上,升级JDK版本确实能带来一些“免费的”性能提升。
图 5-8 运行在JDK 1.6下取消字节码验证的启动时间
前面说过,除了类加载时间以外,在VisualGC的监视曲线中显示了两项很大的非用户程序耗时:编译时间(Compile Time)和垃圾收集时间(GC Time)。垃圾收集时间读者应该非常清楚了,而编译时间是什么呢?程序在运行之前不是已经编译了吗?虚拟机的JIT编译与垃圾收集一样,是本书的一个重要部分,后面有专门章节讲解,这里先简单介绍一下:编译时间是指虚拟机的JIT编译器(Just In Time Compiler)编译热点代码(Hot Spot Code)的耗时。我们知道Java语言为了实现跨平台的特性,Java代码编译出来后形成的Class文件中存储的是字节码(ByteCode),虚拟机通过解释方式执行字节码命令,比起C/C++编译成本地二进制代码来说,速度要慢不少。为了解决程序解释执行的速度问题,JDK 1.2以后,虚拟机内置了两个运行时编译器[3],如果一段Java方法被调用次数达到一定程度,就会被判定为热代码交给JIT编译器即时编译为本地代码,提高运行速度(这就是HotSpot虚拟机名字的由来)。甚至有可能在运行期动态编译比C/C++的编译期静态译编出来的代码更优秀,因为运行期可以收集很多编译器无法知道的信息,甚至可以采用一些很激进的优化手段,在优化条件不成立的时候再逆优化退回来。所以Java程序只要代码没有问题(主要是泄漏问题,如内存泄漏、连接泄漏),随着代码被编译得越来越彻底,运行速度应当是越运行越快的。Java的运行期编译最大的缺点就是它进行编译需要消耗程序正常的运行时间,这也就是上面所说的“编译时间”。
虚拟机提供了一个参数-Xint禁止编译器运作,强制虚拟机对字节码采用纯解释方式执行。如果读者想使用这个参数省下Eclipse启动中那2秒的编译时间获得一个“更好看”的成绩的话,那恐怕要失望了,加上这个参数之后,虽然编译时间确实下降到0,但Eclipse启动的总时间剧增到27秒。看来这个参数现在最大的作用似乎就是让用户怀念一下JDK 1.2之前那令人心酸和心碎的运行速度。
与解释执行相对应的另一方面,虚拟机还有力度更强的编译器:当虚拟机运行在-client模式的时候,使用的是一个代号为C1的轻量级编译器,另外还有一个代号为C2的相对重量级的编译器能提供更多的优化措施,如果使用-server模式的虚拟机启动Eclipse将会使用到C2编译器,这时从VisualGC可以看到启动过程中虚拟机使用了超过15秒的时间去进行代码编译。如果读者的工作习惯是长时间不关闭Eclipse的话,C2编译器所消耗的额外编译时间最终还是会在运行速度的提升之中赚回来,这样使用-server模式也是一个不错的选择。不过至少在本次实战中,我们还是继续选用-client虚拟机来运行Eclipse。
[1]http://www.oracle.com/technetwork/java/6-performance-137236.html。
[2]关于JDK 1.6与JDK 1.5在Eclipse启动时类加载速度差异的讨论:http://www.iteye.com/topic/826542。
[3]JDK 1.2之前也可以使用外挂JIT编译器进行本地编译,但只能与解释器二选其一,不能同时工作。
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工作,所以需要预留较多内存,读者在实际调优时不妨再设置大一些。
5.3.5 选择收集器降低延迟
现在Eclipse启动已经比较迅速了,但我们的调优实战还没有结束,毕竟Eclipse是拿来写程序的,不是拿来测试启动速度的。我们不妨再在Eclipse中测试一个非常常用但又比较耗时的操作:代码编译。图5-11是当前配置下Eclipse进行代码编译时的运行数据,从图中可以看出,新生代每次回收耗时约65毫秒,老年代每次回收耗时约725毫秒。对于用户来说,新生代GC的耗时还好,65毫秒在使用中无法察觉到,而老年代每次GC停顿接近1秒钟,虽然比较长时间才会出现一次,但停顿还是显得太长了一些。
图 5-11 编译期间运行数据
再注意看一下编译期间的CPU资源使用状况。图5-12是Eclipse在编译期间的CPU使用率曲线图,整个编译过程中平均只使用了不到30%的CPU资源,垃圾收集的CPU使用率曲线更是几乎与坐标横轴紧贴在一起,这说明CPU资源还有很多可利用的余地。
图 5-12 编译期间CPU曲线
列举GC停顿时间、CPU资源富余的目的,都是为了接下来替换掉Client模式的虚拟机中默认的新生代、老年代串行收集器做铺垫。
Eclipse应当算是与使用者交互非常频繁的应用程序,由于代码太多,笔者习惯在做全量编译或者清理动作的时候,使用“Run in Backgroup”功能一边编译一边继续工作。回顾一下在第3章提到的几种收集器,很容易想到CMS是最符合这类场景的收集器。因此尝试在eclipse.ini中再加入这两个参数-XX:+UseConcMarkSweepGC、-XX:+UseParNewGC(ParNew收集器是使用CMS收集器后的默认新生代收集器,写上仅是为了配置更加清晰),要求虚拟机在新生代和老年代分别使用ParNew和CMS收集器进行垃圾回收。指定收集器之后,再次测试的结果如图5-13所示,与原来使用串行收集器对比,新生代停顿从每次65毫秒下降到了每次53毫秒,而老年代的停顿时间更是从725毫秒大幅下降到了36毫秒。
图 5-13 指定ParNew和CMS收集器后的GC数据
当然,CMS的停顿阶段只是收集过程中的一小部分,并不是真的把垃圾收集时间从725毫秒变成36毫秒了。在GC日志中可以看到CMS与程序并发的时间约为400毫秒,这样收集器的运作结果就比较令人满意了。
到此,对于虚拟机内存的调优基本就结束了,这次实战可以看做是一次简化的服务端调优过程,因为服务端调优有可能还会存在于更多方面,如数据库、资源池、磁盘I/O等,但对于虚拟机内存部分的优化,与这次实战中的思路没有什么太大差别。即使读者实际工作中接触不到服务器,根据自己工作环境做一些试验,总结几个参数让自己日常工作环境速度有较大幅度提升也是很划算的。最终eclipse.ini的配置如代码清单5-12所示。
代码清单5-12 修改收集器配置后的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 -Dcom.sun.management.jmxremote -Dosgi.requiredJavaVersion=1.5 -Xverify:none -Xmx512m -Xms512m -Xmn128m -XX:PermSize=96m -XX:MaxPermSize=96m -XX:+DisableExplicitGC -Xnoclassgc -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=85
如果你对这篇内容有疑问,欢迎到本站社区发帖提问 参与讨论,获取更多帮助,或者扫码二维码加入 Web 技术交流群。
绑定邮箱获取回复消息
由于您还没有绑定你的真实邮箱,如果其他用户或者作者回复了您的评论,将不能在第一时间通知您!
发布评论