一、性能监控与故障处理
此图来自互联网:http://uule.iteye.com/blog/2114697
1.1 概述
经过前面两章对于虚拟机内存分配与回收技术各方面的介绍,相信读者已经建立了一套比较完整的理论基础。
理论总是作为指导实践的工具,能把这些知识应用到实际工作中才是我们的最终目的。接下来的两章,我们将从实践的角度去了解虚拟机内存管理的世界。
给一个系统定位问题的时候,知识、经验是关键基础,数据是依据,工具是运用知识处理数据的手段。
这里说的数据包括:运行日志、异常堆栈、GC日志、线程快照(threaddump/javacore文件)、堆转储快照(heapdump/hprof文件)等。
经常使用适当的虚拟机监控和分析的工具可以加快我们分析数据、定位解决问题的速度,但在学习工具前,也应当意识到工具永远都是知识技能的一层包装,没有什么工具是“秘密武器”,不可能学会了就能包治百病。
1.2 JDK的命令行工具
Java开发人员肯定都知道JDK的bin目录中有“java.exe”、“javac.exe”这两个命令行工具,但并非所有程序员都了解过JDK的bin目录之中其他命令行程序的作用。
每逢JDK更新版本之时,bin目录下命令行工具的数量和功能总会不知不觉地增加和增强。bin目录的内容如图4-1所示。
在本章中,笔者将介绍这些工具的其中一部分,主要包括用于监视虚拟机和故障处理的工具。这些故障处理工具被Sun公司作为“礼物”附赠给JDK的使用者,并在软件的使用说明中把它们声明为“没有技术支持并且是实验性质的”(unsupported and experimental)[注释]的产品,但事实上,这些工具都非常稳定而且功能强大,能在处理应用程序性能问题、定位故障时发挥很大的作用。
说起JDK的工具,比较细心的读者,可能会注意到这些工具的程序体积都异常小巧。假如以前没注意到,现在不妨再看看图4-1中的最后一列“大小”,几乎所有工具的体积基本上都稳定在27KB左右。并非JDK开发团队刻意把它们制作得如此精炼来炫耀编程水平,而是因为这些命令行工具大多数是jdk/lib/tools.jar类库的一层薄包装而已,它们主要的功能代码是在tools类库中实现的。读者把图4-1和图4-2两张图片对比一下就可以看得很清楚。
假如读者使用的是Linux版本的JDK,还会发现这些工具中很多甚至就是由Shell脚本直接写成的,可以用vim直接打开它们。
JDK开发团队选择采用Java代码来实现这些监控工具是有特别用意的:当应用程序部署到生产环境后,无论是直接接触物理服务器还是远程Telnet到服务器上都可能会受到限制。借助tools.jar类库里面的接口,我们可以直接在应用程序中实现功能强大的监控分析功能[注释]。
需要特别说明的是,本章介绍的工具全部基于Windows平台下的JDK 1.6 Update 21,如果JDK版本、操作系统不同,工具所支持的功能可能会有较大差别。大部分工具在JDK 1.5中就已经提供,但为了避免运行环境带来的差异和兼容性问题,建议读者使用JDK 1.6来验证本章介绍的内容,因为JDK 1.6的工具可以正常兼容运行于JDK 1.5的虚拟机之上的程序,反之则不一定。表4-1中说明了JDK主要命令行监控工具的用途。
注意 如果读者在工作中需要监控运行于JDK 1.5的虚拟机之上的程序,在程序启动时请添加参数“-Dcom.sun.management.jmxremote”开启JMX管理功能,否则由于部分工具都是基于JMX(包括4.3节介绍的可视化工具),它们都将会无法使用,如果被监控程序运行于JDK 1.6的虚拟机之上,那JMX管理默认是开启的,虚拟机启动时无须再添加任何参数。
1.3 jps:虚拟机进程状况工具
JDK的很多小工具的名字都参考了UNIX命令的命名方式,jps(JVM Process Status Tool)是其中的典型。除了名字像UNIX的ps命令之外,它的功能也和ps命令类似:可以列出正在运行的虚拟机进程,并显示虚拟机执行主类(Main Class,main()函数所在的类)名称以及这些进程的本地虚拟机唯一ID(Local Virtual Machine Identifier,LVMID)。虽然功能比较单一,但它是使用频率最高的JDK命令行工具,因为其他的JDK工具大多需要输入它查询到的LVMID来确定要监控的是哪一个虚拟机进程。对于本地虚拟机进程来说,LVMID与操作系统的进程ID(Process Identifier,PID)是一致的,使用Windows的任务管理器或者UNIX的ps命令也可以查询到虚拟机进程的LVMID,但如果同时启动了多个虚拟机进程,无法根据进程名称定位时,那就只能依赖jps命令显示主类的功能才能区分了。
jsp命令格式:
1.4 jstat:虚拟机统计信息监视工具
jstat(JVM Statistics Monitoring Tool)是用于监视虚拟机各种运行状态信息的命令行工具。它可以显示本地或者远程[注释]虚拟机进程中的类装载、内存、垃圾收集、JIT编译等运行数据,在没有GUI图形界面,只提供了纯文本控制台环境的服务器上,它将是运行期定位虚拟机性能问题的首选工具。
jstat命令格式为:
对于命令格式中的VMID与LVMID需要特别说明一下:如果是本地虚拟机进程,VMID与LVMID是一致的,如果是远程虚拟机进程,那VMID的格式应当是:
参数interval和count代表查询间隔和次数,如果省略这两个参数,说明只查询一次。假设需要每250毫秒查询一次进程2764垃圾收集状况,一共查询20次,那命令应当是:
选项option代表着用户希望查询的虚拟机信息,主要分为3类:类装载、垃圾收集、运行期编译状况,具体选项及作用请参考表4-3中的描述。
【代码清单】4-1 jstat执行样例
查询结果表明:这台服务器的新生代Eden区(E,表示Eden)使用了6.2%的空间,两个Survivor区(S0、S1,表示Survivor0、Survivor1)里面都是空的,老年代(O,表示Old)和永久代(P,表示Permanent)则分别使用了41.42%和47.20%的空间。程序运行以来共发生Minor GC(YGC,表示Young GC)16次,总耗时0.105秒,发生Full GC(FGC,表示Full GC)3次,Full GC总耗时(FGCT,表示Full GC Time)为0.472秒,所有GC总耗时(GCT,表示GC Time)为0.577秒。
使用jstat工具在纯文本状态下监视虚拟机状态的变化,确实不如后面将会提到的VisualVM等可视化的监视工具直接以图表展现那样直观。但许多服务器管理员都习惯了在文本控制台中工作,直接在控制台中使用jstat命令依然是一种常用的监控方式。
1.5 jinfo:Java配置信息工具
jinfo(Configuration Info for Java)的作用是实时地查看和调整虚拟机各项参数。使用jps命令的-v参数可以查看虚拟机启动时显式指定的参数列表,但如果想知道未被显式指定的参数的系统默认值,除了去找资料外,就只能使用jinfo的-flag选项进行查询了(如果只限于JDK 1.6或以上版本的话,使用java-XX:+PrintFlagsFinal查看参数默认值也是一个很好的选择),jinfo还可以使用-sysprops选项把虚拟机进程的System.getProperties()的内容打印出来。这个命令在JDK 1.5时期已经随着Linux版的JDK发布,当时只提供了信息查询的功能,JDK 1.6之后,jinfo在Windows和Linux平台都有提供,并且加入了运行期修改参数的能力,可以使用-flag[+|-]name或者-flag name=value修改一部分运行期可写的虚拟机参数值。JDK 1.6中,jinfo对于Windows平台功能仍然有较大限制,只提供了最基本的-flag选项。
jinfo命令格式:
[代码]
执行样例:查询CMSInitiatingOccupancyFraction参数值。
1.6、jmap:Java内存映像工具
jmap(Memory Map for Java)命令用于生成堆转储快照(一般称为heapdump或dump文件)。如果不使用jmap命令,要想获取Java堆转储快照,还有一些比较“暴力”的手段:譬如在第2章中用过的-XX:+HeapDumpOnOutOfMemoryError参数,可以让虚拟机在OOM异常出现之后自动生成dump文件,通过-XX:+HeapDumpOnCtrlBreak参数则可以使用[Ctrl]+[Break]键让虚拟机生成dump文件,又或者在Linux系统下通过Kill-3命令发送进程退出信号“吓唬”一下虚拟机,也能拿到dump文件。
jmap的作用并不仅仅是为了获取dump文件,它还可以查询finalize执行队列、Java堆和永久代的详细信息,如空间使用率、当前用的是哪种收集器等。
和jinfo命令一样,jmap有不少功能在Windows平台下都是受限的,除了生成dump文件的-dump选项和用于查看每个类的实例、空间占用统计的-histo选项在所有操作系统都提供之外,其余选项都只能在Linux/Solaris下使用。
jmap命令格式:
option选项的合法值与具体含义见表4-4。
【代码清单】4-2是使用jmap生成一个正在运行的Eclipse的dump快照文件的例子,例子中的3500是通过jps命令查询到的LVMID。
1.7 jhat:虚拟机堆转储快照分析工具
Sun JDK提供jhat(JVM Heap Analysis Tool)命令与jmap搭配使用,来分析jmap生成的堆转储快照。jhat内置了一个微型的HTTP/HTML服务器,生成dump文件的分析结果后,可以在浏览器中查看。不过实事求是地说,在实际工作中,除非笔者手上真的没有别的工具可用,否则一般都不会去直接使用jhat命令来分析dump文件,主要原因有二:一是一般不会在部署应用程序的服务器上直接分析dump文件,即使可以这样做,也会尽量将dump文件复制到其他机器[注释]上进行分析,因为分析工作是一个耗时而且消耗硬件资源的过程,既然都要在其他机器进行,就没有必要受到命令行工具的限制了;另一个原因是jhat的分析功能相对来说比较简陋,后文将会介绍到的VisualVM,以及专业用于分析dump文件的Eclipse Memory Analyzer、IBM HeapAnalyzer[注释]等工具,都能实现比jhat更强大更专业的分析功能。【代码清单】4-3演示了使用jhat分析4.2.4节中采用jmap生成的Eclipse IDE的内存快照文件。
屏幕显示“Server is ready.”的提示后,用户在浏览器中键入http://localhost:7000/就可以看到分析结果,如图4-3所示。
分析结果默认是以包为单位进行分组显示,分析内存泄漏问题主要会使用到其中的“Heap Histogram”(与jmap-histo功能一样)与OQL页签的功能,前者可以找到内存中总容量最大的对象,后者是标准的对象查询语言,使用类似SQL的语法对内存中的对象进行查询统计,读者若对OQL有兴趣的话,可以参考本书附录D的介绍。
1.8、jstack:Java堆栈跟踪工具
jstack(Stack Trace for Java)命令用于生成虚拟机当前时刻的线程快照(一般称为threaddump或者javacore文件)。线程快照就是当前虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待等都是导致线程长时间停顿的常见原因。线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做些什么事情,或者等待着什么资源。
jstack命令格式:
option选项的合法值与具体含义见表4-5。
在JDK 1.5中,java.lang.Thread类新增了一个getAllStackTraces()方法用于获取虚拟机中所有线程的StackTraceElement对象。使用这个方法可以通过简单的几行代码就完成jstack的大部分功能,在实际项目中不妨调用这个方法做个管理员页面,可以随时使用浏览器来查看线程堆栈,如【代码清单】4-5所示,这是笔者的一个小经验。
1.9 HSDIS:JIT生成代码反汇编
在Java虚拟机规范中,详细描述了虚拟机指令集中每条指令的执行过程、执行前后对操作数栈、局部变量表的影响等细节。
这些细节描述与Sun的早期虚拟机(Sun Classic VM)高度吻合,但随着技术的发展,高性能虚拟机真正的细节实现方式已经渐渐与虚拟机规范所描述的内容产生了越来越大的差距,虚拟机规范中的描述逐渐成了虚拟机实现的“概念模型”——即实现只能保证规范描述等效。基于这个原因,我们分析程序的执行语义问题(虚拟机做了什么)时,在字节码层面上分析完全可行,但分析程序的执行行为问题(虚拟机是怎样做的、性能如何)时,在字节码层面上分析就没有什么意义了,需要通过其他方式解决。
分析程序如何执行,通过软件调试工具(GDB、Windbg等)来断点调试是最常见的手段,但是这样的调试方式在Java虚拟机中会遇到很大困难,因为大量执行代码是通过JIT编译器动态生成到CodeBuffer中的,没有很简单的手段来处理这种混合模式的调试(不过相信虚拟机开发团队内部肯定是有内部工具的)。因此,不得不通过一些特别的手段来解决问题,基于这种背景,本节的主角——HSDIS插件就正式登场了。
HSDIS是一个Sun官方推荐的HotSpot虚拟机JIT编译代码的反汇编插件,它包含在HotSpot虚拟机的源码之中,但没有提供编译后的程序。在Project Kenai的网站[注释]也可以下载到单独的源码。它的作用是让HotSpot的-XX:+PrintAssembly指令调用它来把动态生成的本地代码还原为汇编代码输出,同时还生成了大量非常有价值的注释,这样我们就可以通过输出的代码来分析问题。读者可以根据自己的操作系统和CPU类型从Project Kenai的网站上下载编译好的插件,直接放到JDK_HOME/jre/bin/client和JDK_HOME/jre/bin/server目录中即可。如果没有找到所需操作系统(譬如Windows的就没有)的成品,那就得自己使用源码编译一下[注释]。
还需要注意的是,如果读者使用的是Debug或者FastDebug版的HotSpot,那可以直接通过-XX:+PrintAssembly指令使用插件;如果使用的是Product版的HotSpot,那还要额外加入一个-XX:+UnlockDiagnosticVMOptions参数。笔者以【代码清单】4-6中的简单测试代码为例演示一下这个插件的使用。
编译这段代码,并使用以下命令执行。
【代码清单】4-7 测试代码
其中,参数-Xcomp是让虚拟机以编译模式执行代码,这样代码可以“偷懒”,不需要执行足够次数来预热就能触发JIT编译[注释]。两个-XX:CompileCommand意思是让编译器不要内联sum()并且只编译sum(),-XX:+PrintAssembly就是输出反汇编内容。如果一切顺利的话,那么屏幕上会出现类似下面【代码清单】4-7所示的内容。
上段代码并不多,下面一句句进行说明。
1)mov%eax,-0x8000(%esp):检查栈溢。
2)push%ebp:保存上一栈帧基址。
3)sub$0x18,%esp:给新帧分配空间。
4)mov 0x8(%ecx),%eax:取实例变量a,这里0x8(%ecx)就是ecx+0x8的意思,前面“[Constants]”节中提示了“this:ecx='test/Bar'”,即ecx寄存器中放的就是this对象的地址。偏移0x8是越过this对象的对象头,之后就是实例变量a的内存位置。这次是访问“Java堆”中的数据。
5)mov$0x3d2fad8,%esi:取test.Bar在方法区的指针。
6)mov 0x68(%esi),%esi:取类变量b,这次是访问“方法区”中的数据。
7)add%esi,%eax和add%edx,%eax:做两次加法,求a+b+c的值,前面的代码把a放在eax中,把b放在esi中,而c在[Constants]中提示了,“parm0:edx=int”,说明c在edx中。
8)add$0x18,%esp:撤销栈帧。
9)pop%ebp:恢复上一栈帧。
10)test%eax,0x2b0100:轮询方法返回处的SafePoint。
11)ret:方法返回。
二、 JDK的可视化工具
JDK中除了提供大量的命令行工具外,还有两个功能强大的可视化工具:JConsole和VisualVM,这两个工具是JDK的正式成员,没有被贴上“unsupported and experimental”的标签。
其中JConsole是在JDK 1.5时期就已经提供的虚拟机监控工具,而VisualVM在JDK 1.6 Update7中才首次发布,现在已经成为Sun(Oracle)主力推动的多合一故障处理工具[注释],并且已经从JDK中分离出来成为可以独立发展的开源项目。
为了避免本节的讲解成为对软件说明文档的简单翻译,笔者准备了一些代码样例,都是笔者特意编写的“反面教材”。后面将会使用这两款工具去监控、分析这几段代码存在的问题,算是本节简单的实战分析。读者可以把在可视化工具观察到的数据、现象,与前面两章中讲解的理论知识互相印证。
2.1 JConsole:Java监视与管理控制台
JConsole(Java Monitoring and Management Console)是一种基于JMX的可视化监视、管理工具。它管理部分的功能是针对JMX MBean进行管理,由于MBean可以使用代码、中间件服务器的管理控制台或者所有符合JMX规范的软件进行访问,所以本节将会着重介绍JConsole监视部分的功能。
1.启动JConsole
通过JDK/bin目录下的“jconsole.exe”启动JConsole后,将自动搜索出本机运行的所有虚拟机进程,不需要用户自己再使用jps来查询了,如图4-4所示。双击选择其中一个进程即可开始监控,也可以使用下面的“远程进程”功能来连接远程服务器,对远程虚拟机进行监控。
从图4-4可以看出,笔者的机器现在运行了Eclipse、JConsole和MonitoringTest三个本地虚拟机进程,其中MonitoringTest就是笔者准备的“反面教材”代码之一。双击它进入JConsole主界面,可以看到主界面里共包括“概述”、“内存”、“线程”、“类”、“VM摘要”、“MBean”6个页签,如图4-5所示。
“概述”页签显示的是整个虚拟机主要运行数据的概览,其中包括“堆内存使用情况”、“线程”、“类”、“CPU使用情况”4种信息的曲线图,这些曲线图是后面“内存”、“线程”、“类”页签的信息汇总,具体内容将在后面介绍。
2.内存监控
“内存”页签相当于可视化的jstat命令,用于监视受收集器管理的虚拟机内存(Java堆和永久代)的变化趋势。我们通过运行【代码清单】4-8中的代码来体验一下它的监视功能。运行时设置的虚拟机参数为:-Xms100m-Xmx100m-XX:+UseSerialGC,这段代码的作用是以64KB/50毫秒的速度往Java堆中填充数据,一共填充1000次,使用JConsole的“内存”页签进行监视,观察曲线和柱状指示图的变化。
【代码清单】4-8 JConsole监视代码
程序运行后,在“内存”页签中可以看到内存池Eden区的运行趋势呈现折线状,如图4-6所示。而监视范围扩大至整个堆后,会发现曲线是一条向上增长的平滑曲线。并且从柱状图可以看出,在1000次循环执行结束,运行了System.gc()后,虽然整个新生代Eden和Survivor区都基本被清空了,但是代表老年代的柱状图仍然保持峰值状态,说明被填充进堆中的数据在System.gc()方法执行之后仍然存活。笔者的分析到此为止,现提两个小问题供读者思考一下,答案稍后给出。
1)虚拟机启动参数只限制了Java堆为100MB,没有指定-Xmn参数,能否从监控图中估计出新生代有多大?
2)为何执行了System.gc()之后,图4-6中代表老年代的柱状图仍然显示峰值状态,代码需要如何调整才能让System.gc()回收掉填充到堆中的对象?
问题1答案:图4-6显示Eden空间为27 328KB,因为没有设置-XX:SurvivorRadio参数,所以Eden与Survivor空间比例为默认值8:1,整个新生代空间大约为27 328KB×125%=34 160KB。
问题2答案:执行完System.gc()之后,空间未能回收是因为List<OOMObject>list对象仍然存活,fillHeap()方法仍然没有退出,因此list对象在System.gc()执行时仍然处于作用域之内[注释]。如果把System.gc()移动到fillHeap()方法外调用就可以回收掉全部内存。
3.线程监控
如果上面的“内存”页签相当于可视化的jstat命令的话,“线程”页签的功能相当于可视化的jstack命令,遇到线程停顿时可以使用这个页签进行监控分析。前面讲解jstack命令的时候提到过线程长时间停顿的主要原因主要有:等待外部资源(数据库连接、网络资源、设备资源等)、死循环、锁等待(活锁和死锁)。通过【代码清单】4-9分别演示一下这几种情况。
【代码清单】4-9 线程等待演示代码
程序运行后,首先在“线程”页签中选择main线程,如图4-7所示。堆栈追踪显示BufferedReader在readBytes方法中等待System.in的键盘输入,这时线程为Runnable状态,Runnable状态的线程会被分配运行时间,但readBytes方法检查到流没有更新时会立刻归还执行令牌,这种等待只消耗很小的CPU资源。
了一个无法再被激活的死锁等待。
这段代码开了200个线程去分别计算1+2以及2+1的值,其实for循环是可省略的,两个线程也可能会导致死锁,不过那样概率太小,需要尝试运行很多次才能看到效果。一般的话,带for循环的版本最多运行2~3次就会遇到线程死锁,程序无法结束。造成死锁的原因是Integer.valueOf()方法基于减少对象创建次数和节省内存的考虑,[-128,127]之间的数字会被缓存[注释],当valueOf()方法传入参数在这个范围之内,将直接返回缓存中的对象。也就是说,代码中调用了200次Integer.valueOf()方法一共就只返回了两个不同的对象。假如在某个线程的两个synchronized块之间发生了一次线程切换,那就会出现线程A等着被线程B持有的Integer.valueOf(1),线程B又等着被线程A持有的Integer.valueOf(2),结果出现大家都跑不下去的情景。
出现线程死锁之后,点击JConsole线程面板的“检测到死锁”按钮,将出现一个新的“死锁”页签,如图4-10所示。
图4-10中很清晰地显示了线程Thread-43在等待一个被线程Thread-12持有Integer对象,而点击线程Thread-12则显示它也在等待一个Integer对象,被线程Thread-43持有,这样两个线程就互相卡住,都不存在等到锁释放的希望了。
2.2 VisualVM:多合一故障处理工具
VisualVM(All-in-One Java Troubleshooting Tool)是到目前为止随JDK发布的功能最强大的运行监视和故障处理程序,并且可以预见在未来一段时间内都是官方主力发展的虚拟机故障处理工具。官方在VisualVM的软件说明中写上了“All-in-One”的描述字样,预示着它除了运行监视、故障处理外,还提供了很多其他方面的功能。如性能分析(Profiling),VisualVM的性能分析功能甚至比起JProfiler、YourKit等专业且收费的Profiling工具都不会逊色多少,而且VisualVM的还有一个很大的优点:不需要被监视的程序基于特殊Agent运行,因此它对应用程序的实际性能的影响很小,使得它可以直接应用在生产环境中。这个优点是JProfiler、YourKit等工具无法与之媲美的。
1.VisualVM兼容范围与插件安装
VisualVM基于NetBeans平台开发,因此它一开始就具备了插件扩展功能的特性,通过插件扩展支持,VisualVM可以做到:
显示虚拟机进程以及进程的配置、环境信息(jps、jinfo)。
监视应用程序的CPU、GC、堆、方法区以及线程的信息(jstat、jstack)。
dump以及分析堆转储快照(jmap、jhat)。
方法级的程序运行性能分析,找出被调用最多、运行时间最长的方法。
离线程序快照:收集程序的运行时配置、线程dump、内存dump等信息建立一个快照,可以将快照发送开发者处进行Bug反馈。
其他plugins的无限的可能性……
VisualVM在JDK 1.6 update 7中才首次出现,但并不意味着它只能监控运行于JDK 1.6上的程序,它具备很强的向下兼容能力,甚至能向下兼容至近10年前发布的JDK 1.4.2平台[注释],这对无数已经处于实施、维护的项目很有意义。当然,并非所有功能都能完美地向下兼容,主要特性的兼容性见表4-6。
首次启动VisualVM后,读者先不必着急找应用程序进行监测,因为现在VisualVM还没有加载任何插件,虽然基本的监视、线程面板的功能主程序都以默认插件的形式提供了,但是不给VisualVM装任何扩展插件,就相当于放弃了它最精华的功能,和没有安装任何应用软件操作系统差不多。
插件可以进行手工安装,在相关网站[注释]上下载*.nbm包后,点击“工具”→“插件”→“已下载”菜单,然后在弹出的对话框中指定nbm包路径便可进行安装,插件安装后存放在JDK_HOME/lib/visualvm/visualvm中。不过手工安装并不常用,使用VisualVM的自动安装功能已经可以找到大多数所需的插件,在有网络连接的环境下,点击“工具”→“插件菜单”,弹出如图4-11所示的插件页签,在页签的“可用插件”中列举了当前版本VisualVM可以使用的插件,选中插件后在右边窗口将显示这个插件的基本信息,如开发者、版本、功能描述等。
大家可以根据自己的工作需要和兴趣选择合适的插件,然后点击安装按钮,弹出如图4-12所示的下载进度窗口,跟着提示操作即可完成安装。
安装完插件,选择一个需要监视的程序就进入程序的主界面了,如图4-13所示。根据读者选择安装插件数量的不同,看到的页签可能和图4-13中的有所不同。
VisualVM中“概述”、“监视”、“线程”、“MBeans”的功能与前面介绍的JConsole差别不大,读者根据上文内容类比使用即可,下面挑选几个特色功能、插件进行介绍。
2.生成、浏览堆转储快照
在VisualVM中生成dump文件有两种方式,可以执行下列任一操作:
在“应用程序”窗口中右键单击应用程序节点,然后选择“堆Dump”。
在“应用程序”窗口中双击应用程序节点以打开应用程序标签,然后在“监视”标签中单击“堆Dump”。
生成了dump文件之后,应用程序页签将在该堆的应用程序下增加一个以[heapdump]开头的子节点,并且在主页签中打开了该转储快照,如图4-14所示。如果需要把dump文件保存或发送出去,要在heapdump节点上右键选择“另存为”菜单,否则当VisualVM关闭时,生成的dump文件会被当做临时文件删除掉。要打开一个已经存在的dump文件,通过文件菜单中的“装入”功能,选择硬盘上的dump文件即可。
从堆页签中的“摘要”面板可以看到应用程序dump时的运行时参数、System.getProperties()的内容、线程堆栈等信息,“类”面板则是以类为统计口径统计类的实例数量、容量信息,“实例”面板不能直接使用,因为不能确定用户想查看哪个类的实例,所以需要通过“类”面板进入,在“类”中选择一个关心的类后双击鼠标,即可在“实例”里面看见此类中500个实例的具体属性信息。“OQL控制台”面板中就是运行OQL查询语句的,同jhat中介绍的OQL功能一样。如果需要了解具体OQL语法和使用,可参见本书附录D的内容。
3.分析程序性能
在Profiler页签中,VisualVM提供了程序运行期间方法级的CPU执行时间分析以及内存分析,做Profiling分析肯定会对程序运行性能有比较大的影响,所以一般不在生产环境中使用这项功能。
要开始分析,先选择“CPU”和“内存”按钮中的一个,然后切换到应用程序中对程序进行操作,VisualVM会记录到这段时间中应用程序执行过的方法。如果是CPU分析,将会统计每个方法的执行次数、执行耗时;如果是内存分析,则会统计每个方法关联的对象数以及这些对象所占的空间。分析结束后,点击“停止”按钮结束监控过程,如图4-15所示。
注意 在JDK 1.5之后,在Client模式下的虚拟机加入并且自动开启了类共享——这是一个在多虚拟机进程中共享rt.jar中类数据以提高加载速度和节省内存的优化,而根据相关Bug报告的反映,VisualVM的Profiler功能可能会因为类共享而导致被监视的应用程序崩溃,所以读者进行Profiling前,最好在被监视程序中使用-Xshare:off参数来关闭类共享优化。
图4-15中是对Eclipse IDE一段操作的录制和分析结果,读者分析自己的应用程序时,可以根据实际业务的复杂程度与方法的时间、调用次数做比较,找到最有优化价值的方法。
4.BTrace动态日志跟踪
BTrace[注释]是一个很“有趣”的VisualVM插件,本身也是可以独立运行的程序。它的作用是在不停止目标程序运行的前提下,通过HotSpot虚拟机的HotSwap技术[注释]动态加入原本并不存在的调试代码。这项功能对实际生产中的程序很有意义:经常遇到程序出现问题,但排查错误的一些必要信息,譬如方法参数、返回值等,在开发时并没有打印到日志之中,以至于不得不停掉服务,通过调试增量来加入日志代码以解决问题。当遇到生产环境服务无法随便停止时,缺一两句日志导致排错进行不下去是一件非常郁闷的事情。
在VisualVM中安装了BTrace插件后,在应用程序面板中右键点击要调试的程序,会出现“Trace Application……”菜单,点击将进入BTrace面板。这个面板里面看起来就像一个简单的Java程序开发环境,里面还有一小段Java代码,如图4-16所示。
笔者准备了一段很简单的Java代码来演示BTrace的功能:产生两个1000以内的随机整数,输出这两个数字相加的结果,如【代码清单】4-11所示。
【代码清单】4-11 BTrace跟踪演示
程序运行后,在VisualVM中打开该程序的监视,在BTrace页签填充TracingScript的内容,输入的调试代码如【代码清单】4-12所示。
BTrace的用法还有许多,打印调用堆栈、参数、返回值只是最基本的应用,在它的网站上有使用BTrace进行性能监视、定位连接泄漏和内存泄漏、解决多线程竞争问题等例子,有兴趣的读者可以去相关网站了解一下。
5、 本章小结
本章介绍了随JDK发布的6个命令行工具及两个可视化的故障处理工具,灵活使用这些工具可以给问题处理带来很大的便利。
除了JDK自带的工具之外,常用的故障处理工具还有很多,如果读者使用的是非Sun系列的JDK、非HotSpot的虚拟机,就需要使用对应的工具进行分析,如:
IBM的Support Assistant[注释]、Heap Analyzer[注释]、Javacore Analyzer[注释]、Garbage Collector Analyzer[注释]适用于IBM J9 VM。
HP的HPjmeter[注释]、HPjtune适用于HP-UX、SAP、HotSpot VM。
Eclipse的Memory Analyzer Tool[注释](MAT)适用于HP-UX、SAP、HotSpot VM,安装IBM DTFJ插件后可支持IBM J9 VM。
三、调优案例分析与实战
3.1 概述
上文介绍了处理Java虚拟机内存问题的知识与工具,在处理实际项目的问题时,除了知识与工具外,经验同样是一个很重要的因素。
因此本章将与读者分享几个比较有代表性的实际案例。考虑到虚拟机故障处理和调优主要面向各类服务端应用,而大部分Java程序员较少有机会直接接触生产环境的服务器,因此本章还准备了一个所有开发人员都能够进行“亲身实战”的练习,希望通过实践使读者获得故障处理和调优的经验。
3.2 案例分析
本章中的案例大部分来源于笔者处理过的一些问题,还有一小部分来源于网络上比较有特色和代表性的案例总结。出于对客户商业信息保护的目的,在不影响前后逻辑的前提下,笔者对实际环境和用户业务做了一些屏蔽和精简。
3.2.1 高性能硬件上的程序部署策略
例如,一个15万PV/天左右的在线文档类型网站最近更换了硬件系统,新的硬件为4个CPU、16GB物理内存,操作系统为64位CentOS 5.4,Resin作为Web服务器。整个服务器暂时没有部署别的应用,所有硬件资源都可以提供给这访问量并不算太大的网站使用。管理员为了尽量利用硬件资源选用了64位的JDK 1.5,并通过-Xmx和-Xms参数将Java堆固定在12GB。使用一段时间后发现使用效果并不理想,网站经常不定期出现长时间失去响应的情况。
监控服务器运行状况后发现网站失去响应是由GC停顿导致的,虚拟机运行在Server模式,默认使用吞吐量优先收集器,回收12GB的堆,一次Full GC的停顿时间高达14秒。并且由于程序设计的关系,访问文档时要把文档从磁盘提取到内存中,导致内存中出现很多由文档序列化产生的大对象,这些大对象很多都进入了老年代,没有在Minor GC中清理掉。这种情况下即使有12GB的堆,内存也很快被消耗殆尽,由此导致每隔十几分钟出现十几秒的停顿,令网站开发人员和管理员感到很沮丧。
这里先不延伸讨论程序代码问题,程序部署上的主要问题显然是过大的堆内存进行回收时带来的长时间的停顿。硬件升级前使用32位系统1.5GB的堆,用户只感觉到使用网站比较缓慢,但不会发生十分明显的停顿,因此才考虑升级硬件以提升程序效能,如果重新缩小给Java堆分配的内存,那么硬件上的投资就显得很浪费。
在高性能硬件上部署程序,目前主要有两种方式:
通过64位JDK来使用大内存。
使用若干个32位虚拟机建立逻辑集群来利用硬件资源。
此案例中的管理员采用了第一种部署方式。对于用户交互性强、对停顿时间敏感的系统,可以给Java虚拟机分配超大堆的前提是有把握把应用程序的Full GC频率控制得足够低,至少要低到不会影响用户使用,譬如十几个小时乃至一天才出现一次Full GC,这样可以通过在深夜执行定时任务的方式触发Full GC甚至自动重启应用服务器来保持内存可用空间在一个稳定的水平。
控制Full GC频率的关键是看应用中绝大多数对象能否符合“朝生夕灭”的原则,即大多数对象的生存时间不应太长,尤其是不能有成批量的、长生存时间的大对象产生,这样才能保障老年代空间的稳定。
在大多数网站形式的应用里,主要对象的生存周期都应该是请求级或者页面级的,会话级和全局级的长生命对象相对很少。
只要代码写得合理,应当都能实现在超大堆中正常使用而没有Full GC,这样的话,使用超大堆内存时,网站响应速度才会比较有保证。
除此之外,如果读者计划使用64位JDK来管理大内存,还需要考虑下面可能面临的问题:
内存回收导致的长时间停顿。
现阶段,64位JDK的性能测试结果普遍低于32位JDK。
需要保证程序足够稳定,因为这种应用要是产生堆溢出几乎就无法产生堆转储快照(因为要产生十几GB乃至更大的Dump文件),哪怕产生了快照也几乎无法进行分析。
相同程序在64位JDK消耗的内存一般比32位JDK大,这是由于指针膨胀,以及数据类型对齐补白等因素导致的。
上面的问题听起来有点吓人,所以现阶段不少管理员还是选择第二种方式:使用若干个32位虚拟机建立逻辑集群来利用硬件资源。
具体做法是在一台物理机器上启动多个应用服务器进程,每个服务器进程分配不同端口,然后在前端搭建一个负载均衡器,以反向代理的方式来分配访问请求。
读者不需要太过在意均衡器转发所消耗的性能,即使使用64位JDK,许多应用也不止有一台服务器,因此在许多应用中前端的均衡器总是要存在的。
考虑到在一台物理机器上建立逻辑集群的目的仅仅是为了尽可能利用硬件资源,并不需要关心状态保留、热转移之类的高可用性需求,也不需要保证每个虚拟机进程有绝对准确的均衡负载,因此使用无Session复制的亲合式集群是一个相当不错的选择。我们仅仅需要保障集群具备亲合性,也就是均衡器按一定的规则算法(一般根据SessionID分配)将一个固定的用户请求永远分配到固定的一个集群节点进行处理即可,这样程序开发阶段就基本不用为集群环境做什么特别的考虑了。
当然,很少有没有缺点的方案,如果读者计划使用逻辑集群的方式来部署程序,可能会遇到下面一些问题:
尽量避免节点竞争全局的资源,最典型的就是磁盘竞争,各个节点如果同时访问某个磁盘文件的话(尤其是并发写操作容易出现问题),很容易导致IO异常。
很难最高效率地利用某些资源池,譬如连接池,一般都是在各个节点建立自己独立的连接池,这样有可能导致一些节点池满了而另外一些节点仍有较多空余。
尽管可以使用集中式的JNDI,但这个有一定复杂性并且可能带来额外的性能开销。
各个节点仍然不可避免地受到32位的内存限制,在32位Windows平台中每个进程只能使用2GB的内存,考虑到堆以外的内存开销,堆一般最多只能开到1.5GB。
在某些Linux或UNIX系统(如Solaris)中,可以提升到3GB乃至接近4GB的内存,但32位中仍然受最高4GB(232)内存的限制。
大量使用本地缓存(如大量使用HashMap作为K/V缓存)的应用,在逻辑集群中会造成较大的内存浪费,因为每个逻辑节点上都有一份缓存,这时候可以考虑把本地缓存改为集中式缓存。
介绍完这两种部署方式,再重新回到这个案例之中,最后的部署方案调整为建立5个32位JDK的逻辑集群,每个进程按2GB内存计算(其中堆固定为1.5GB),占用了10GB内存。
另外建立一个Apache服务作为前端均衡代理访问门户。
考虑到用户对响应速度比较关心,并且文档服务的主要压力集中在磁盘和内存访问,CPU资源敏感度较低,因此改为CMS收集器进行垃圾回收。
部署方式调整后,服务再没有出现长时间停顿,速度比硬件升级前有较大提升。
3.2.2 集群间同步导致的内存溢出
有一个基于B/S的MIS系统,硬件为两台2个CPU、8GB内存的HP小型机,服务器是WebLogic 9.2,每台机器启动了3个WebLogic实例,构成一个6个节点的亲合式集群。由于是亲合式集群,节点之间没有进行Session同步,但是有一些需求要实现部分数据在各个节点间共享。开始这些数据存放在数据库中,但由于读写频繁竞争很激烈,性能影响较大,后面使用JBossCache构建了一个全局缓存。全局缓存启用后,服务正常使用了一段较长的时间,但最近却不定期地出现了多次的内存溢出问题。
在内存溢出异常不出现的时候,服务内存回收状况一直正常,每次内存回收后都能恢复到一个稳定的可用空间,开始怀疑是程序某些不常用的代码路径中存在内存泄漏,但管理员反映最近程序并未更新、升级过,也没有进行什么特别操作。
只好让服务带着-XX:+HeapDumpOnOutOfMemoryError参数运行了一段时间。在最近一次溢出之后,管理员发回了heapdump文件,发现里面存在着大量的org.jgroups.protocols.pbcast.NAKACK对象。
JBossCache是基于自家的JGroups进行集群间的数据通信,JGroups使用协议栈的方式来实现收发数据包的各种所需特性自由组合,数据包接收和发送时要经过每层协议栈的up()和down()方法,其中的NAKACK栈用于保障各个包的有效顺序及重发。JBossCache协议栈如图5-1所示。
由于信息有传输失败需要重发的可能性,在确认所有注册在GMS(Group Membership Service)的节点都收到正确的信息前,发送的信息必须在内存中保留。而此MIS的服务端中有一个负责安全校验的全局Filter,每当接收到请求时,均会更新一次最后操作时间,并且将这个时间同步到所有的节点去,使得一个用户在一段时间内不能在多台机器上登录。在服务使用过程中,往往一个页面会产生数次乃至数十次的请求,因此这个过滤器导致集群各个节点之间网络交互非常频繁。当网络情况不能满足传输要求时,重发数据在内存中不断堆积,很快就产生了内存溢出。
这个案例中的问题,既有JBossCache的缺陷,也有MIS系统实现方式上缺陷。JBossCache官方的maillist中讨论过很多次类似的内存溢出异常问题,据说后续版本也有了改进。而更重要的缺陷是这一类被集群共享的数据要使用类似JBossCache这种集群缓存来同步的话,可以允许读操作频繁,因为数据在本地内存有一份副本,读取的动作不会耗费多少资源,但不应当有过于频繁的写操作,那样会带来很大的网络同步的开销。
3.2.3 堆外内存导致的溢出错误
例如,一个学校的小型项目:基于B/S的电子考试系统,为了实现客户端能实时地从服务器端接收考试数据,系统使用了逆向AJAX技术(也称为Comet或者Server Side Push),选用CometD 1.1.1作为服务端推送框架,服务器是Jetty 7.1.4,硬件为一台普通PC机,Core i5 CPU,4GB内存,运行32位Windows操作系统。
测试期间发现服务端不定时抛出内存溢出异常,服务器不一定每次都会出现异常,但假如正式考试时崩溃一次,那估计整场电子考试都会乱套,网站管理员尝试过把堆开到最大,而32位系统最多到1.6GB就基本无法再加大了,而且开大了基本没效果,抛出内存溢出异常好像还更加频繁了。加入-XX:+HeapDumpOnOutOfMemoryError,居然也没有任何反应,抛出内存溢出异常时什么文件都没有产生。无奈之下只好挂着jstat并一直紧盯屏幕,发现GC并不频繁,Eden区、Survivor区、老年代以及永久代内存全部都表示“情绪稳定,压力不大”,但就是照样不停地抛出内存溢出异常,管理员压力很大。最后,在内存溢出后从系统日志中找到异常堆栈,如【代码清单】5-1所示。
如果认真阅读过本书的第2章,看到异常堆栈就应该清楚这个抛出内存溢出异常是怎么回事了。
大家知道操作系统对每个进程能管理的内存是有限制的,这台服务器使用的32位Windows平台的限制是2GB,其中划了1.6GB给Java堆,而Direct Memory内存并不算入1.6GB的堆之内,因此它最大也只能在剩余的0.4GB空间中分出一部分。
在此应用中导致溢出的关键是:垃圾收集进行时,虚拟机虽然会对Direct Memory进行回收,但是Direct Memory却不能像新生代、老年代那样,发现空间不足了就通知收集器进行垃圾回收,它只能等待老年代满了后Full GC,然后“顺便地”帮它清理掉内存的废弃对象。
否则它只能一直等到抛出内存溢出异常时,先catch掉,再在catch块里面“大喊”一声:“System.gc()!”。
要是虚拟机还是不听(譬如打开了-XX:+DisableExplicitGC开关),那就只能眼睁睁地看着堆中还有许多空闲内存,自己却不得不抛出内存溢出异常了。而本案例中使用的CometD 1.1.1框架,正好有大量的NIO操作需要使用到Direct Memory内存。
从实践经验的角度出发,除了Java堆和永久代之外,我们注意到下面这些区域还会占用较多的内存,这里所有的内存总和受到操作系统进程最大内存的限制。
Direct Memory:可通过-XX:MaxDirectMemorySize调整大小,内存不足时抛出OutOfMemoryError或者OutOfMemoryError:Direct buffer memory。
线程堆栈:可通过-Xss调整大小,内存不足时抛出StackOverflowError(纵向无法分配,即无法分配新的栈帧)或者OutOfMemoryError:unable to create new native thread(横向无法分配,即无法建立新的线程)。
Socket缓存区:每个Socket连接都Receive和Send两个缓存区,分别占大约37KB和25KB内存,连接多的话这块内存占用也比较可观。如果无法分配,则可能会抛出IOException:Too many open files异常。
JNI代码:如果代码中使用JNI调用本地库,那本地库使用的内存也不在堆中。
虚拟机和GC:虚拟机、GC的代码执行也要消耗一定的内存。
3.2.4 外部命令导致系统缓慢
这是一个来自网络的案例:一个数字校园应用系统,运行在一台4个CPU的Solaris 10操作系统上,中间件为GlassFish服务器。系统在做大并发压力测试的时候,发现请求响应时间比较慢,通过操作系统的mpstat工具发现CPU使用率很高,并且系统占用绝大多数的CPU资源的程序并不是应用系统本身。这是个不正常的现象,通常情况下用户应用的CPU占用率应该占主要地位,才能说明系统是正常工作的。
通过Solaris 10的Dtrace脚本可以查看当前情况下哪些系统调用花费了最多的CPU资源,Dtrace运行后发现最消耗CPU资源的竟然是“fork”系统调用。众所周知,“fork”系统调用是Linux用来产生新进程的,在Java虚拟机中,用户编写的Java代码最多只有线程的概念,不应当有进程的产生。
这是个非常异常的现象。通过本系统的开发人员,最终找到了答案:每个用户请求的处理都需要执行一个外部shell脚本来获得系统的一些信息。执行这个shell脚本是通过Java的Runtime.getRuntime().exec()方法来调用的。这种调用方式可以达到目的,但是它在Java虚拟机中是非常消耗资源的操作,即使外部命令本身能很快执行完毕,频繁调用时创建进程的开销也非常可观。
Java虚拟机执行这个命令的过程是:首先克隆一个和当前虚拟机拥有一样环境变量的进程,再用这个新的进程去执行外部命令,最后再退出这个进程。如果频繁执行这个操作,系统的消耗会很大,不仅是CPU,内存负担也很重。
用户根据建议去掉这个Shell脚本执行的语句,改为使用Java的API去获取这些信息后,系统很快恢复了正常。
3.2.5 服务器JVM进程崩溃
例如,一个基于B/S的MIS系统,硬件为两台2个CPU、8GB内存的HP系统,服务器是WebLogic 9.2(就是5.2.2节中的那套系统)。
正常运行一段时间后,最近发现在运行期间频繁出现集群节点的虚拟机进程自动关闭的现象,留下了一个hs_err_pid###.log文件后,进程就消失了,两台物理机器里的每个节点都出现过进程崩溃的现象。
从系统日志中可以看出,每个节点的虚拟机进程在崩溃前不久,都发生过大量相同的异常,见【代码清单】5-2。
这是一个远端断开连接的异常,通过系统管理员了解到系统最近与一个OA门户做了集成,在MIS系统工作流的待办事项变化时,要通过Web服务通知OA门户系统,把待办事项的变化同步到OA门户之中。
通过SoapUI测试了一下同步待办事项的几个Web服务,发现调用后竟然需要长达3分钟才能返回,并且返回结果都是连接中断。
由于MIS系统的用户多,待办事项变化很快,为了不被OA系统速度拖累,使用了异步的方式调用Web服务,但由于两边服务速度的完全不对等,时间越长就累积了越多Web服务没有调用完成,导致在等待的线程和Socket连接越来越多,最终在超过虚拟机的承受能力后使得虚拟机进程崩溃。
解决方法:通知OA门户方修复无法使用的集成接口,并将异步调用改为生产者/消费者模式的消息队列实现后,系统恢复正常。
3.2.6 不恰当数据结构导致内存占用过大
例如,有一个后台RPC服务器,使用64位虚拟机,内存配置为-Xms4g-Xmx8g-Xmn1g,使用ParNew+CMS的收集器组合。平时对外服务的Minor GC时间约在30毫秒以内,完全可以接受。
但业务上需要每10分钟加载一个约80MB的数据文件到内存进行数据分析,这些数据会在内存中形成超过100万个HashMap<Long,Long>Entry,在这段时间里面Minor GC就会造成超过500毫秒的停顿,对于这个停顿时间就接受不了了,具体情况如下面GC日志所示。
观察这个案例,发现平时的Minor GC时间很短,原因是新生代的绝大部分对象都是可清除的,在Minor GC之后Eden和Survivor基本上处于完全空闲的状态。
而在分析数据文件期间,800MB的Eden空间很快被填满从而引发GC,但Minor GC之后,新生代中绝大部分对象依然是存活的。我们知道ParNew收集器使用的是复制算法,这个算法的高效是建立在大部分对象都“朝生夕灭”的特性上的,如果存活对象过多,把这些对象复制到Survivor并维持这些对象引用的正确就成为一个沉重的负担,因此导致GC暂停时间明显变长。
如果不修改程序,仅从GC调优的角度去解决这个问题,可以考虑将Survivor空间去掉(加入参数-XX:SurvivorRatio=65536、-XX:MaxTenuringThreshold=0或者-XX:+AlwaysTenure),让新生代中存活的对象在第一次Minor GC后立即进入老年代,等到Major GC的时候再清理它们。这种措施可以治标,但也有很大副作用,治本的方案需要修改程序,因为这里的问题产生的根本原因是用HashMap<Long,Long>结构来存储数据文件空间效率太低。
下面具体分析一下空间效率。在HashMap<Long,Long>结构中,只有Key和Value所存放的两个长整型数据是有效数据,共16B(2×8B)。这两个长整型数据包装成java.lang.Long对象之后,就分别具有8B的MarkWord、8B的Klass指针,在加8B存储数据的long值。在这两个Long对象组成Map.Entry之后,又多了16B的对象头,然后一个8B的next字段和4B的int型的hash字段,为了对齐,还必须添加4B的空白填充,最后还有HashMap中对这个Entry的8B的引用,这样增加两个长整型数字,实际耗费的内存为(Long(24B)×2)+Entry(32B)+HashMap Ref(8B)=88B,空间效率为16B/88B=18%,实在太低了。
3.2.7 由Windows虚拟内存导致的长时间停顿
例如,有一个带心跳检测功能的GUI桌面程序,每15秒会发送一次心跳检测信号,如果对方30秒以内都没有信号返回,那就认为和对方程序的连接已经断开。程序上线后发现心跳检测有误报的概率,查询日志发现误报的原因是程序会偶尔出现间隔约一分钟左右的时间完全无日志输出,处于停顿状态。[注释]
因为是桌面程序,所需的内存并不大(-Xmx256m),所以开始并没有想到是GC导致的程序停顿,但是加入参数-XX:+PrintGCApplicationStoppedTime-XX:+PrintGCDateStamps-Xloggc:gclog.log后,从GC日志文件中确认了停顿确实是由GC导致的,大部分GC时间都控制在100毫秒以内,但偶尔就会出现一次接近1分钟的GC。
从GC日志中找到长时间停顿的具体日志信息(添加了-XX:+PrintReferenceGC参数),找到的日志片段如下所示。从日志中可以看出,真正执行GC动作的时间不是很长,但从准备开始GC,到真正开始GC之间所消耗的时间却占了绝大部分。
除GC日志之外,还观察到这个GUI程序内存变化的一个特点,当它最小化的时候,资源管理中显示的占用内存大幅度减小,但是虚拟内存则没有变化,因此怀疑程序在最小化时它的工作内存被自动交换到磁盘的页面文件之中了,这样发生GC时就有可能因为恢复页面文件的操作而导致不正常的GC停顿。
在MSDN上查证[注释]后确认了这种猜想,因此,在Java的GUI程序中要避免这种现象,可以加入参数“-Dsun.awt.keepWorkingSetOnMinimize=true”来解决。这个参数在许多AWT的程序上都有应用,例如JDK自带的Visual VM,用于保证程序在恢复最小化时能够立即响应。在这个案例中加入该参数后,问题得到解决。
四、实战:Eclipse运行速度调优
很多Java开发人员都有这样一种观念:系统调优的工作都是针对服务端应用而言,规模越大的系统,就越需要专业的调优运维团队参与。这个观点不能说不对,5.2节中笔者所列举的案例确实都是服务端运维、调优的例子,但服务端应用需要调优,并不说明其他应用就不需要了,作为一个普通的Java开发人员,前面讲的各种虚拟机的原理和最佳实践方法距离我们并不遥远,开发者身边很多场景都可以使用上面这些知识。下面通过一个普通程序员日常工作中可以随时接触到的开发工具开始这次实战。
4.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初始配置
为了要与调优后的结果进行量化对比,调优开始前笔者先做了一次初始数据测试。测试用例很简单,就是收集从Eclipse启动开始,直到所有插件加载完成为止的总耗时以及运行状态数据,虚拟机的运行数据通过VisualVM及其扩展插件VisualGC进行采集。测试过程中反复启动数次Eclipse直到测试结果稳定后,取最后一次运行的结果作为数据样本(为了避免操作系统未能及时进行磁盘缓存而产生的影响),数据样本如图5-2所示。
Eclipse启动的总耗时没有办法从监控工具中直接获得,因为VisualVM不可能知道Eclipse运行到什么阶段算是启动完成。为了测试的准确性,笔者写了一个简单的Eclipse插件,用于统计Eclipse的启动耗时。由于代码很简单,并且本书不是Eclipse RCP开发的教程,所以只列出【代码清单】5-4供读者参考,不再延伸讲解。如果读者需要这个插件,可以使用下面代码自行编译或者发电子邮件向笔者索取。
●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在启动后的使用过程中经常有不时停顿的感觉,所以进行调优有较大的价值。
4.2 升级JDK 1.6的性能变化及兼容问题
对Eclipse进行调优的第一步就是先把虚拟机的版本进行升级,希望能先从虚拟机版本身上得到一些“免费的”性能提升。
每次JDK的大版本发布时,开发商肯定都会宣称虚拟机的运行速度比上一版本有了很大的提高,这虽然是个广告性质的宣言,经常被人从升级列表或者技术白皮书中直接忽略过去,但从国内外的第三方评测数据来看,版本升级至少某些方面确实带来了一定的性能改善[注释],以下是一个第三方网站对JDK 1.5、1.6、1.7三个版本做的性能评测,分别测试了以下4个用例[注释]:
生成500万个的字符串。
500万次ArrayList<String>数据插入,使用第一点生成的数据。
生成500万个HashMap<String,Integer>,每个键-值对通过并发线程计算,测试并发能力。
打印500万个ArrayList<String>中的值到文件,并重读回内存。
三个版本的JDK分别运行这3个用例的测试程序,测试结果如图5-4所示。
从这4个用例的测试结果来看,JDK 1.6比JDK 1.5有大约15%的性能提升,尽管对JDK仅测试这4个用例并不能说明什么问题,需要通过测试数据来量化描述一个JDK比旧版提升了多少是很难做到非常科学和准确的(要做稍微靠谱一点的测试,可以使用SPECjvm2008[注释]来完成,或者把相应版本的TCK[注释]中数万个测试用例的性能数据对比一下可能更有说服力),但我还是选择相信这次“软广告”性质的测试,把JDK版本升级到1.6 Update 21。
与所有小说作者设计的故事情节一样,获得最后的胜利之前总是要经历各种各样的挫折,这次升级到JDK 1.6之后,性能有什么变化先暂且不谈,在使用几分钟之后,笔者的Eclipse就和前面几个服务端的案例一样非常“不负众望”地发生了内存溢出,如图5-5所示。
这次内存溢出完全出乎笔者的意料之外:决定对Eclipse做调优是因为速度慢,但开发环境一直都很稳定,至少没有出现过内存溢出的问题,而这次升级除了eclipse.ini中的JVM路径改变了之外,还未进行任何运行参数的调整,进到Eclipse主界面之后随便打开了几个文件就抛出内存溢出异常了,难道JDK 1.6 Update 21
有哪个API出现了严重的泄漏问题吗?
事实上,并不是JDK 1.6出现了什么问题,根据前面章节中介绍的相关原理和工具,我们要查明这个异常的原因并且解决它一点也不困难。打开VisualVM,监视页签中的内存曲线部分如图5-6和图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运行期参数
而使用JDK 1.5运行时,就有4条JVM参数,其中多出来的一条正好就是设置永久代最大容量的-XX:MaxPermSize=256M,如【代码清单】5-6所示。
【代码清单】5-6 JDK 1.5的Eclipse运行期参数
为什么会这样呢?笔者从Eclipse的Bug List网站[注释]上找到了答案:使用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这个参数就可以了。
4.3 编译时间和类加载时间的优化
从Eclipse启动时间上来看,升级到JDK 1.6所带来的性能提升是……嗯?基本上没有提升?多次测试的平均值与JDK 1.5的差距完全在实验误差范围之内。
各位读者不必失望,Sun JDK 1.6性能白皮书[注释]描述的众多相对于JDK 1.5的
提升不至于全部是广告,虽然总启动时间没有减少,但在查看运行细节的时候,却发现了一件很值得注意的事情:在JDK 1.6中启动完Eclipse所消耗的类加载时间比JDK 1.5长了接近一倍,不要看反了,这里写的是JDK 1.6的类加载比JDK 1.5慢一倍,测试结果如【代码清单】5-7所示,反复测试多次仍然是相似的结果
在本例中,类加载时间上的差距并不能作为一个具有普遍性的测试结果去说明JDK 1.6的类加载必然比JDK 1.5慢,笔者测试了自己机器上的Tomcat和GlassFish启动过程,并未没有出现类似的差距。在国内最大的Java社区中,笔者发起过关于此问题的讨论[注释],从参与者反馈的测试结果来看,此问题只在一部分机器上存在,而且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.5的平均启动下降到了13秒,而JDK 1.6的测试数据平均比JDK 1.5快1秒,下降到平均12秒左右,如图5-8所示。在类加载时间仍然落后的情况下,依然可以看到JDK 1.6在性能上比JDK 1.5稍有优势,说明至少在Eclipse启动这个测试用例上,升级JDK版本确实能带来一些“免费的”性能提升。
前面说过,除了类加载时间以外,在VisualGC的监视曲线中显示了两项很大的非用户程序耗时:编译时间(Compile Time)和垃圾收集时间(GC Time)。垃圾收集时间读者应该非常清楚了,而编译时间是什么呢?程序在运行之前不是已经编译了吗?虚拟机的JIT编译与垃圾收集一样,是本书的一个重要部分,后面有专门章节讲解,这里先简单介绍一下:编译时间是指虚拟机的JIT编译器(Just In Time Compiler)编译热点代码(Hot Spot Code)的耗时。我们知道Java语言为了实现跨平台的特性,Java代码编译出来后形成的Class文件中存储的是字节码(ByteCode),虚拟机通过解释方式执行字节码命令,比起C/C++编译成本地二进制代码来说,速度要慢不少。为了解决程序解释执行的速度问题,JDK 1.2以后,虚拟机内置了两个运行时编译器[注释],如果一段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。
4.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条,每当发生一次垃圾收集动作,所有用户线程[注释]都必须跑到最近的一个安全点(SafePoint)然后挂起线程等待垃圾回收。这样过于频繁的GC就会导致很多没有必要的安全点检测、线程挂起及恢复操作。
新生代GC频繁发生,很明显是由于虚拟机分配给新生代的空间太小而导致的,Eden区加上一个Survivor区还不到35MB。因此很有必要使用-Xmn参数调整新生代的大小。
再来看一看那19次Full GC,看起来19次并“不多”(相对于378次Minor GC来说),但总耗时为3.166秒,占了GC时间的绝大部分,降低GC时间的主要目标就要降低这部分时间。从VisualGC的曲线图上可能看得不够精确,这次直接从GC日志[注释]中分析一下这些Full GC是如何产生的,【代码清单】5-9中是启动最开始的2.5秒内发生的10次Full GC记录。
【代码清单】5-9 Full GC记录
括号中加粗的数字代表老年代的容量,这组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参数值一样,这样就强制虚拟机在启动的时候就把老年代和永久代的容量固定下来,避免运行时自动扩展[注释]。
根据分析,优化计划确定为:把新生代容量提升到128MB,避免新生代频繁GC;把Java堆、永久代的容量分别固定为512MB和96MB[注释],避免内存扩展。这几个数值都是根据机器硬件、Eclipse插件和工程数量来决定的,读者实践的时候应根据VisualGC中收集到的实际数据进行设置。改动后的eclipse.ini配置如【代码清单】5-10所示。
中加入参数-XX:+DisableExplicitGC屏蔽掉System.gc()。再次测试发现启动期间的Full GC已经完全没有了,只有6次Minor GC,耗时417毫秒,与调优前4.149秒的测试样本相比,正好是十分之一。进行GC调优后Eclipse的启动时间下降非常明显,比整个GC时间降低的绝对值还大,现在启动只需要7秒多,如图5-10所示。
4.5 选择收集器降低延迟
现在Eclipse启动已经比较迅速了,但我们的调优实战还没有结束,毕竟Eclipse是拿来写程序的,不是拿来测试启动速度的。我们不妨再在Eclipse中测试一个非常常用但又比较耗时的操作:代码编译。图5-11是当前配置下Eclipse进行代码编译时的运行数据,从图中可以看出,新生代每次回收耗时约65毫秒,老年代每次回收耗时约725毫秒。对于用户来说,新生代GC的耗时还好,65毫秒在使用中无法察觉到,而老年代每次GC停顿接近1秒钟,虽然比较长时间才会出现一次,但停顿还是显得太长了一些。
再注意看一下编译期间的CPU资源使用状况。图5-12是Eclipse在编译期间的CPU使用率曲线图,整个编译过程中平均只使用了不到30%的CPU资源,垃圾收集的CPU使用率曲线更是几乎与坐标横轴紧贴在一起,这说明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毫秒。
当然,CMS的停顿阶段只是收集过程中的一小部分,并不是真的把垃圾收集时间从725毫秒变成36毫秒了。在GC日志中可以看到CMS与程序并发的时间约为400毫秒,这样收集器的运作结果就比较令人满意了。
到此,对于虚拟机内存的调优基本就结束了,这次实战可以看做是一次简化的服务端调优过程,因为服务端调优有可能还会存在于更多方面,如数据库、资源池、磁盘I/O等,但对于虚拟机内存部分的优化,与这次实战中的思路没有什么太大差别。即使读者实际工作中接触不到服务器,根据自己工作环境做一些试验,总结几个参数让自己日常工作环境速度有较大幅度提升也是很划算的。最终eclipse.ini的配置如【代码清单】5-12所示。
4.6 本章小结
Java虚拟机的内存管理与垃圾收集是虚拟机结构体系中最重要的组成部分,对程序的性能和稳定性有非常大的影响,在本书的第2~5章中,笔者从理论知识、异常现象、代码、工具、案例、实战等几个方面对其进行了讲解,希望读者有所收获。
本书关于虚拟机内存管理部分到此为止就结束了,后面将开始介绍Class文件与虚拟机执行子系统方面的知识。
来源:深入理解java虚拟机 作者: 周志明。