虚拟机调优案例分析与实战

虚拟机调优案例分析与实战


一. 案例分析

虚拟机性能监控和故障处理工具介绍了处理Java虚拟机内存问题的知识与工具,在处理实际项目的问题时,除了知识与工具外,经验也是一个很重要的因素。

1.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(2^32)内存的限制。
  • 大量使用本地缓存(如大量使用HashMap作为K/V缓存)的应用,在逻辑集群中会造成较大的内存浪费,因为每个逻辑节点上都有一份缓存,这时可以考虑把本地缓存改为集中式缓存。

介绍完这两种部署方式,再重新回到这个案例之中,最后的部署方案调整为建立5个32位JDK的逻辑集群,每个进程按2GB内存计算(其中堆固定为1.5GB),占用了10GB的内存。另外建立一个Apache服务作为前端均衡代理访问门户。考虑到用户对响应速度比较关心,并且文档服务的主要压力集中在磁盘和内存访问上,CPU资源敏感度较低,因此改为CMS收集器进行垃圾回收。部署方式调整后,服务再没有出现长时间停顿,速度比硬件升级前有较大提升。

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所示。

JBossCache协议栈

由于信息有传输失败需要重发的可能性,在确认所有注册在GMS(Group Membership Service)的节点都收到正确的信息前,发送的信息必须在内存中保留。而此MIS的服务端中有一个负责安全校验的全局Filter,每当接收到请求时,均会更新一次最后的操作时间,并且将这个时间同步到所有的节点中,使得一个用户在一段时间内不能在多台机器上登录。在服务使用过程中,往往一个页面会产生数次乃至数十次的请求,因此这个过滤器导致集群各个节点之间的网络交互非常频繁。当网络情况不能满足传输要求时,重发数据在内存中不断地堆积,很快就产生了内存溢出。

这个案例中的问题,既有JBossCache的缺陷,也有MIS系统实现方式上的缺陷。JBossCache官方的maillist中讨论过很多次类似的内存溢出异常问题,据说后续版本有了改进。而更重要的缺陷是这一类被集群共享的数据如果要使用类似JBossCache这种集群缓存来同步的话,可以允许读操作频繁,因为数据在本地内存有一份副本,读取的动作不会耗费多少资源,但不应当有过于频繁的写操作,这会带来很大的网络同步的开销。

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所示。

1
2
3
4
5
6
7
代码清单5-1 异常堆栈1
[org.eclipse.jetty.util.log]handle failed java.lang.OutOfMemoryError:null
at sun.misc.Unsafe.allocateMemory(Native Method)
at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:99)
at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:288)
at org.eclipse.jetty.io.nio.DirectNIOBuffer.<init>
……

如果认真阅读过第2章,看到异常堆栈就应该清楚这个内存溢出异常是怎么回事了。大家知道操作系统对每个进程能管理的内存是有限制的,这台服务器使用的32位Windows平台的限制是2GB,其中给了Java堆1.6GB,而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的代码执行也要消耗一定的内存。

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去获取这些信息后,系统很快就恢复了正常。

2.5 服务器JVM进程崩溃

一个基于B/S的MIS系统,硬件为两台2个CPU、8GB内存的HP系统,服务器是 WebLogic 9.2(就是第二个案例中的那套系统)。正常运行一段时间后,最近发现在运行期间频繁出现集群节点的虚拟机进程自动关闭的现象,留下了一个 hs_err_pid###.log 文件后,进程就消失了,两台物理机器里的每个节点都出现过进程崩溃的现象。从系统日志中注意到,每个节点的虚拟机进程在崩溃前不久,都发生过大量相同的异常,见代码清单5-2。

1
2
3
4
5
6
7
8
代码清单5-2 异常堆栈2
java.net.SocketException:Connection reset
at java.net.SocketInputStream.read(SocketInputStream.java:168)
at java.io.BufferedInputStream.fill(BufferedInputStream.java: 218)
at java.io.BufferedInputStream.read(BufferedInputStream.java:235)
at org.apache.axis.transport.http.HTTPSender.readHeadersFromSocket(HTTPSe 583)
at org.apache.axis.transport.http.HTTPSender.invoke(HTTPSender.java: 143)
……99 more

这是一个远端断开连接的异常,通过系统管理员了解到系统最近与一个OA门户做了集成,在MIS系统工作流的待办事项变化时,要通过Web服务通知OA门户系统,把待办事项的变化同步到OA门户之中。通过SoapUI测试了一下同步待办事项的几个Web服务,发现调用后竟然需要长达3分钟才能返回,并且返回的结果都是连接中断。

由于MIS系统的用户多,待办事项变化很快,为了不被OA系统的速度拖累,使用了异步的方式调用Web服务,但由于两边服务的速度完全不对等,时间越长就累积了越多Web服务没有调用完成,导致在等待的线程和Socket连接越来越多,最终超过虚拟机的承受能力后使得虚拟机进程崩溃。通知OA门户方修复无法使用的集成接口,并将异步调用改为生产者/消费者模式的消息队列实现后,系统恢复正常。

2.6 不恰当数据结构导致内存占用过大

例如,有一个后台RPC服务器,使用64位虚拟机,内存配置为 -Xms4g -Xmx8g -Xmnlg ,使用ParNew+CMS的收集器组合。平时对外服务的Minor GC时间约在30毫秒以内,完全可以接受。但业务上需要每10分钟加载一个约80MB的数据文件到内存进行数据分析,这些数据会在内存中形成超过100万个 HashMap<Long, Long>Entry ,在这段时间里面Minor GC就会造成超过500毫秒的停顿,这个时间就有些接受不了了,具体情况如下面GC日志所示。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
{Heap before GC invocations=95(full 4):
par new generation total 903168K,used 803142K[0x00002aaaae7700000x00002aaaebb700000x00002aaaebb70000)
eden space 802816K,100%used[0x00002aaaae7700000x00002aaadf7700000x00002aaadf770000)
from space 100352K,0%used[0x00002aaae59700000x00002aaae59c19100x00002aaaebb70000)
to space 100352K,0%used[0x00002aaadf7700000x00002aaadf7700000x00002aaae5970000)
concurrent mark-sweep generation total 5845540K,used 3898978K[0x00002aaaebb700000x00002aac507f90000x00002aacae770000)
concurrent-mark-sweep perm gen total 65536K,used 40333K[0x00002aacae7700000x00002aacb27700000x00002aacb2770000)
2011-10-28 T 11:40:45.162+0800: 226.504:[GC 226.504: [ParNew:803142K->100352K(903168K),0.5995670 secs] 4702120K-> 4056332K(6748708K),0.5997560 secs][Times:user=1.46 sys=0.04,real=0.60 secs]
Heap after GC invocations=96(full 4):
par new generation total 903168K,used 100352K[0x00002aaaae7700000x00002aaaebb700000x00002aaaebb70000)
eden space 802816K,0%used[0x00002aaaae7700000x00002aaaae7700000x00002aaadf770000)
from space 100352K,100%used[0x00002aaadf7700000x00002aaae59700000x00002aaae5970000)
to space 100352K,0x00002aaaebb70000)0%used[0x00002aaae59700000x00002aaae5970000
concurrent mark-sweep generation total 5845540K,used 3955980K[0x00002aaaebb700000x00002aac507f90000x00002aacae770000)
concurrent-mark-sweep perm gen total 65536K,used 40333K[0x00002aacae7700000x00002aacb27700000x00002aacb2770000)
}
Total time for which application threads were stopped:0.6070570 seconds

观察这个案例,发现平时的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%,实在太低了。

2.7 由Windows虚拟内存导致的长时间停顿

例如,有一个带心跳检测功能的GUI桌面程序,每15秒会发送一次心跳检测信号,如果对方30秒以内都没有信号返回,那就认为和对方程序的连接已经断开。程序上线后发现心跳检测有误报的概率,查询日志发现误报的原因是程序会偶尔出现间隔约一分钟左右的时间完全无日志输出,处于停顿状态。

因为是桌面程序,所需的内存并不大(-Xmx256m),所以开始并没有想到是GC导致的程序停顿,但是加入参数 -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps Xloggc:gclog.log 后,从GC日志文件中确认了停顿确实是由GC导致的,大部分GC时间都控制在100毫秒以内,但偶尔就会出现一次接近1分钟的GC。

1
2
3
4
5
6
7
8
Total time for which application threads were stopped:0.0112389 seconds
Total time for which application threads were stopped:0.0001335 seconds
Total time for which application threads were stopped:0.0003246 seconds
Total time for which application threads were stopped:41.4731411 seconds
Total time for which application threads were stopped:0.0489481 seconds
Total time for which application threads were stopped:0.1110761 seconds
Total time for which application threads were stopped:0.0007286 seconds
Total time for which application threads were stopped:0.0001268 seconds

从GC日志中找到长时间停顿的具体日志信息(添加了 -XX:+PrintReferenceGC 参数),找到的日志片段如下所示。从日志中可以看出,真正执行GC动作的时间不是很长,但从准备开始GC,到真正开始GC之间所消耗的时间却占了绝大部分。

1
2012-08-29T191430.968+080010069.800:[GC10099.225:[SoftReference,0 refs,0.0000109 secs]10099.226:[WeakReference,4072 refs,0.0012099 secs]10099.227:[FinalReference,984 refs,1.5822450 secs]10100.809:[PhantomReference,251 refs,0.0001394 secs]10100.809:[JNI Weak Reference,0.0994015 secs] [PSYoungGen:175672K->8528K(167360K)]251523K->100182K(353152K),31.1580402 secs][Times:user=0.61 sys=0.52,real=31.16 secs]

除GC日志之外,还观察到这个GUI程序内存变化的一个特点,当它最小化的时候,资源管理中显示的占用内存大幅度减小,但是虚拟内存则没有变化,因此怀疑程序在最小化时它的工作内存被自动交换到磁盘的页面文件之中了,这样发生GC时就有可能因为恢复页面文件的操作而导致不正常的GC停顿。

在MSDN上查证后确认了这种猜想,因此,在Java的GUI程序中要避免这种现象,可以加入参数 -Dsun.awt.keepWorkingSetOnMinimize=true 来解决。这个参数在许多AWT的程序上都有应用,例如JDK自带的Visual VM,用于保证程序在恢复最小化时能够立即响应。在这个案例中加入该参数后,问题得到解决。


二. 实战:Eclipse运行速度调优

很多Java开发人员都有这样一种观念:系统调优的工作都是针对服务端应用而言的,规模越大的系统,需要越专业的调优运维团队参与。这个观点不能说不对,上一节中作者所列举的案例确实都是服务端运维和调优的例子,但服务端应用需要调优,并不说明其他应用就不需要了,作为一个普通的Java开发人员,前面讲的各种虚拟机的原理和最佳实践的方法距离我们并不遥远,开发者身边的很多场景都可以使用上面这些知识。下面就通过一个普通程序员日常工作中可以随时接触到的开发工具开始这次实战。

3.1 调优前的程序运行状态

作者使用Eclipse 3.5作为日常工作中的主要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 所示。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
代码清单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所示。

Eclipse原始运行数据

Eclipse启动的总耗时没有办法从监控工具中直接获得,因为VisualVM不可能知道Eclipse运行到什么阶段才算是启动完成。为了保证测试的准确性,作者写了一个简单的Eclipse插件,用于统计Eclipse的启动耗时。由于代码很简单,并且本书不是Eclispe RCP的开发教程,所以只列出代码清单5-4供读者参考,不再延伸讲解。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
// 代码清单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所示。

耗时统计插件运行效果

根据VisualGC和Eclipse插件收集到的信息,总结原始配置下的测试结果如下:

  • 整个启动过程平均耗时约15秒。
  • 最后一次启动的数据样本中,垃圾收集总耗时4.149秒,其中:Full GC被触发了19次,共耗时3.166秒;Minor GC被触发了378次,共耗时0.983秒。
  • 加载类9115个,耗时4.114秒。
  • JIT的编译时间为1.999秒。
  • 虚拟机512MB的堆内存被分配为40MB的新生代(31.5MB的Eden空间和2个4MB的 Surviver空间)及472MB的老年代。

客观地说,由于机器硬件还不错(请读者以2010年普通PC机的标准来衡量),15秒的启动时间其实还在可接受的范围以内,但是从VisualGC中反映的数据来看,主要问题是非用户程序时间(图5-2中的Compile Time、Class Loader Time、GC Time)非常高,占了整个启动过程耗时的一半以上(这里存在少许夸张成分,因为
如果JIT编译等动作是在后台线程完成的,用户程序在此期间也正常执行,所以并没有占用一半以上的绝对时间)。虚拟机后台占用太多时间也直接导致Eclipse在启动后的使用过程中经常有停顿的感觉,所以进行调优有较大的价值。

3.2 升级JDK 1.6的性能变化及兼容问题

对Eclipse进行调优的第一步就是先把虚拟机的版本做个升级,希望能先从虚拟机版本上得到一些“免费的”性能提升。

每次JDK的大版本发布时,开发商肯定都会宣称虚拟机的运行速度比上一版本有了很大的提高,这虽然是个广告性质的宣言,经常被人从升级列表或技术白皮书中直接忽略过去,但从国内外的第三方评测数据来看,版本升级在某些方面确实带来了一定的性能改善,以下是一个第三方网站对JDK 1.5、1.6、1.7三个版本做的性能评测,分别测试了以下四个用例:

  • 生成500万个字符串。
  • 500万次 ArrayList<String> 数据插入,使用第一点生成的数据。
  • 生成500万个 HashMap<String, Integer> ,每个键-值对通过并发线程计算,测试并发能力。
  • 打印500万个 ArrayList<String> 中的值到文件,并重读回内存。

三个版本的JDK分别运行这些用例的测试程序,测试结果如图5-4所示。

JDK横向性能对比

从这4个用例的测试结果来看,JDK 1.6比1.5有大约15%的性能提升,尽管对JDK仅测试这4个用例并不能说明什么问题,需要通过测试数据来量化描述一个JDK比旧版提升了多少是很难做到非常科学准确的(要做稍微靠谱一点的测试,可以使用SPECjvm2008来完成,或者把相应版本的TCK中数万个测试用例的性能数据对比一下可能更有说服力),但我还是选择相信这次“软广告”性质的测试,把JDK版本升级到1.6 Update 21,升级的最主要理由是:本书是基于JDK 1.6编写的。

这次升级到JDK 1.6之后,性能有什么变化暂且不谈,在使用几分钟之后,作者的Eclipse就和前面几个服务端的案例一样“不负众望”地发生了内存溢出,如图5-5所示。

Eclipse OutOfMemoryError

这次内存溢出完全出乎作者的意料:决定对Eclipse做调优是因为速度慢,但开发环境一直都很稳定,至少没有出现过内存溢出的问题,而这次升级除了eclipse.ini中的JVM路径改了之外,还未进行任何运行参数的调整,进到Eclipse主界面之后随便开了几个文件居然就抛出内存溢出异常了,难道JDK 1.6 Update21有哪个API出现了严重的泄漏问题吗?

事实上并不是JDK 1.6出现了什么问题,根据前面讲解的原理和工具,我们要查明这个异常的原因并且解决它一点也不困难。打开VisualVM,监视页签中的内存曲线部分,如图5-6和图5-7所示。

Java堆监视曲线

在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 所示。

1
2
3
4
代码清单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所示。

1
2
3
4
5
代码清单5-6 JDK 1.5的Eclipse运行期参数
-Dcom.sun.management.jmxremote
-Dosgi.requiredJavaVersion=1.5
-Xmx512m
-XX:MaxPermSize=256M

为什么会这样呢?作者从Eclipse的Bug List网站上找到答案:使用JDK 1.5时之所以有永久代容量这个参数,是因为在eclipse.ini中存在 -launcher.XXMaxPermSize 256M 这项设置,当launcher—Windows下的可执行程序eclipse.exe检测到是Eclipse运行在Sun公司的虚拟机上的话,就会把参数值转化为 -XX:MaxPermSize 传递给虚拟机进程,因为三大商用虚拟机中只有Sun系列的虚拟机才有永久代的概念,即只有HotSpot虚拟机需要设置这个参数,JRockit虚拟机和IBM J9虚拟机都不需要设置。

2010年4月10日,Oracle正式完成了对Sun的收购,此后无论是网页还是具体的程序产品,提供商都从Sun变为了Oracle,而eclipse.exe就是根据程序提供商判断是否是Sun的虚拟机,当JDK 1.6 Update21中java.exe、javaw.exe 的“Company”属性从“Sun Microsystems Inc.”变为“Oracle Corporation”之后,Eclipse就完全不认识这个虚拟机了,因此没有把最大永久代的参数传递过去。

了解原因之后,解决方案就简单了,launcher不认识就只好由人来告诉它,在eclipse.ini中明确指定 -XX:MaxPermSize=256M 这个参数就可以了。

3.3 编译时间和类加载时间的优化

从Eclipse启动时间上看,升级到JDK 1.6所带来的性能提升是……嗯?基本上没有提升?多次测试的平均值与JDK 1.5的差距完全在实验误差范围之内。

各位读者不必失望,Sun JDK 1.6性能白皮书描述的众多相对于JDK 1.5的提升不至于全部是广告,虽然总启动时间没有减少,但在查看运行细节的时候,却发现了一件很值得注意的事情:在JDK 1.6中启动完Eclipse所消耗的类加载时间比JDK 1.5长了接近一倍,不要看反了,这里写的是1.6的类加载比1.5慢一倍,测试结果如代码清单5-7所示,反复测试多次仍然是相似的结果。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
代码清单5-7 JDK 1.51.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的类加载必然比1.5慢,作者测试了自己机器上的Tomcat和ClassFish启动过程,并没有出现类似的差距。在国内最大的Java社区中,作者发起过关于此问题的讨论,从参与者反馈的测试结果来看,此问题只在一部分机器上存在,而且JDK 1.6的各个update版之间也存在很大差异。

多次试验后,发现在作者机器上的两个JDK进行类加载时,字节码验证部分的耗时差距尤其严重。考虑到实际情况:Eclipse使用者甚多,它的编译代码我们认为是可靠的,不需要在加载的时候再进行字节码验证,因此通过参数 -Xverify:none 禁止掉字节码验证过程也可作为一项优化措施。加入这个参数后,两个版本的JDK类加载速度都有所提高,JDK 1.6的类加载速度仍然比1.5慢,但是两者的耗时已经接近了许多,测试数据如代码清单5-8所示。关于类与类加载的话题,譬如刚刚提到的字节码验证是怎么回事,本书专门规划了两个章节进行详细讲解,在此不再延伸。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
代码清单5-8 JDK 1.51.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版本确实能带来一些“免费的”性能提升。

运行在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以后,虚拟机内置了两个运行时编译器,如果一段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。

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个,每当发生一次垃圾收集的动作,所有的用户线程都必须跑到最近的一个安全点(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的记录。

1
2
3
4
5
6
7
8
9
10
11
代码清单5-9 Full GC记录
0.278[GC 0.278[DefNew574K-33K576K),0.0012562 secs]0.279[Tenured1467K-997K1536K),0.0181775 secs]1920K-997K2112K),0.0195257 secs]
0.312[GC 0.312[DefNew575K-64K576K),0.0004974 secs]0.312[Tenured1544K-1608K1664K),0.0191592 secs]1980K1608K2240K),0.0197396 secs]
0.590[GC 0.590[DefNew576K-64K576K),0.0006360 secs]0.590[Tenured2675K-2219K2684K),0.0256020 secs]3090K2219K3260K),0.0263501 secs]
0.958[GC 0.958[DefNew551K-64K576K),0.0011433 secs]0.959[Tenured3979K-3470K4084K),0.0419335 secs]4222K3470K4660K),0.0431992 secs]
1.575[Full GC 1.575[Tenured4800K-5046K5784K),0.0543136 secs]5189K-5046K6360K),[Perm12287K-12287K12288K]0.0544163 secs]
1.703[GC 1.703[DefNew703K-63K704K),0.0012609 secs]1.705[Tenured8441K-8505K8540K),0.0607638 secs]8691K8505K9244K),0.0621470 secs]
1.837[GC 1.837[DefNew1151K-64K1152K),0.0020698 secs]1.839[Tenured14616K-14680K14688K),0.0708748 secs]15035K-14680K15840K),0.0730947 secs]
2.144[GC 2.144[DefNew1856K-191K1856K),0.0026810 secs]2.147[Tenured25092K-24656K25108K),0.1112429 secs]26172K-24656K26964K),0.1141099 secs]
2.337[GC 2.337[DefNew1914K-0K3136K),0.0009697 secs]2.338[Tenured41779K-27347K42056K),0.0954341 secs]42733K-27347K45192K),0.0965513 secs]
2.465[GC 2.465[DefNew2490K-0K3456K),0.0011044 secs]2.466[Tenured46379K-27635K46828K),0.0956937 secs]47621K-27635K50284K),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: PermSizeMax 参数值,强制虚拟机在启动的时候就把老年代和永久代的容量固定下来,避免运行时自动扩展。

根据分析,优化计划确定为:

  • 把新生代容量提升到128MB,避免新生代频繁GC;
  • 把Java堆、永久代的容量分别固定为512MB和96MB,避免内存扩展。

这几个数值都是根据机器硬件、Eclipse插件和工程数量来决定的,读者实战的时候应根据VisualGC中收集到的实际数据进行设置。改动后的eclipse.ini配置如代码清单510所示。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
代码清单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秒。

GC调整后的运行数据

这个结果已经算是基本正常,但是还存在一点瑕疵:从Old Gen曲线上看,永久代直接固定在384MB,而内存使用量只有66MB,并且一直很平滑,完全不应该发生Full GC才对,那4次Full GC是怎么来的?

使用jstat-gccause查询一下最近一次GC的原因,见代码清单5-11。

1
2
3
4
5
6
7
8
代码清单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所示。

Eclipse启动时间

3.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毫秒。

指定ParNew和CMS收集器后的GC数据

当然,CMS的停顿阶段只是收集过程中的一小部分,并不是真的把垃圾收集时间从 725毫秒变成36毫秒了。在GC日志中可以看到CMS与程序并发的时间约为400毫秒。不过由于CMS默认老年代使用了68%就进行收集,所以Full GC次数上升到了6次,为了避免总体吞吐量下降得太厉害,使用 -XX:CMSInitiatingOccupancyFraction=85 将GC临界值提升到85%,修改 -XX:CMSInitiatingOccupancyFraction 参数后,Full GC次数下降至3次,这样收集器的运作结果就比较令人满意了。

到这里为止,对于虚拟机内存的调优就基本结束了,这次实战可以看做是一次简化的服务端调优过程,服务端调优有可能还会出现在更多方面,如数据库、资源池、 磁盘I/O等,对于虚拟机内存部分的优化,与这次实战中的思路没有太大差别。即使读者实际工作中接触不到服务器,根据自己的工作环境做一些试验,总结几个参数让自己日常工作环境的速度有较大幅度的提升也是很划算的。最终eclipse.ini的配置如代码清单5-12所示。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
代码清单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

三. JVM调优

3.1 常用指令

查看JVM默认垃圾收集器:

1
$ java -XX:+PrintCommandLineFlags -version

3.2 内存占用分析

(1)TOP指令

查询参数:

  • s – 改变画面更新频率
  • l – 关闭或开启第一部分第一行 top 信息的表示
  • t – 关闭或开启第一部分第二行 Tasks 和第三行 Cpus 信息的表示
  • m – 关闭或开启第一部分第四行 Mem 和 第五行 Swap 信息的表示
  • N – 以 PID 的大小的顺序排列表示进程列表
  • P – 以 CPU 占用率大小的顺序排列进程列表
  • M – 以内存占用率大小的顺序排列进程列表
  • h – 显示帮助
  • n – 设置在进程列表所显示进程的数量
  • q – 退出 top
  • s – 改变画面更新周期

默认情况下仅显示比较重要的 PID、USER、PR、NI、VIRT、RES、SHR、S、%CPU、%MEM、TIME+、COMMAND 列。可以通过下面的快捷键来更改显示内容:

  • 通过 f 键可以选择显示的内容。按 f 键之后会显示列的列表,按 a-z 即可显示或隐藏对应的列,最后按回车键确定。
  • 按 o 键可以改变列的显示顺序。按小写的 a-z 可以将相应的列向右移动,而大写的 A-Z 可以将相应的列向左移动。最后按回车键确定。
  • 按大写的 F 或 O 键,然后按 a-z 可以将进程按照相应的列进行排序。而大写的 R 键可以将当前的排序倒转。

查询结果:

  • PID:进程id。

  • PPID:父进程id。

  • RUSER:Real user name。

  • UID:进程所有者的用户id。

  • USER:进程所有者的用户名。

  • GROUP:进程所有者的组名。

  • TTY:启动进程的终端名。不是从终端启动的进程则显示为 ? 。

  • PR:优先级。

  • NI:nice值。负值表示高优先级,正值表示低优先级。

  • P:最后使用的CPU,仅在多CPU环境下有意义。

  • %CPU:上次更新到现在的CPU时间占用百分比。

  • TIME:进程使用的CPU时间总计,单位秒。

  • **TIME+**:进程使用的CPU时间总计,单位1/100秒。

  • %MEM:进程使用的物理内存百分比。

  • VIRT:virtual memory usage,虚拟内存。进程使用的虚拟内存总量,单位kb,VIRT=SWAP+RES。

    • 进程“需要的”虚拟内存大小,包括进程使用的库、代码、数据等。
    • 假如进程申请100m的内存,但实际只使用了10m,那么它会增长100m,而不是实际的使用量。
  • SWAP:进程使用的虚拟内存中,被换出的大小,单位kb。

  • RES:resident memory usage,常驻内存。进程使用的、未被换出的物理内存大小,单位kb。RES=CODE+DATA。

    • 进程当前使用的内存大小,但不包括swap out。
    • 包含其他进程的共享。
    • 如果申请100m的内存,实际使用10m,它只增长10m,与VIRT相反。
    • 关于库占用内存的情况,它只统计加载的库文件所占内存大小。
  • SHR:shared memory,共享内存大小,单位kb。

    • 除了自身进程的共享内存,也包括其他进程的共享内存。
    • 虽然进程只使用了几个共享库的函数,但它包含了整个共享库的大小。
    • 计算某个进程所占的物理内存大小公式:RES – SHR。
    • swap out后,它将会降下来。
  • CODE:可执行代码占用的物理内存大小,单位kb。

  • DATA:可执行代码以外的部分(数据段+栈)占用的物理内存大小,单位kb。

    • 数据占用的内存。如果top没有显示,按f键可以显示出来。
    • 真正的该程序要求的数据空间,是真正在运行中要使用的。
  • FLT:页面错误次数。

  • nDRT:最后一次写入到现在,被修改过的页面数。

  • S:进程状态,D=不可中断的睡眠状态,R=运行,S=睡眠,T=跟踪/停止,Z=僵尸进程。

  • COMMAND:命令名/命令行。

  • WCHAN:若该进程在睡眠,则显示睡眠中的系统函数名

  • Flags:任务标志,参考 sched.h

(2)ps aux指令

1
2
3
$ ps aux|grep 13870
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
XXX 13870 80.6 5.8 36275316 7766580 ? Sl Oct12 1133:06 java -Xms4096m -Xmx8192m -cp ...

Java进程实际占用内存超过7G,虚拟内存近35G。

返回结果:

  • USER:进程所属用户
  • PID:进程ID
  • %CPU:进程占用CPU百分比
  • %MEM:进程占用内存百分比
  • VSZ:虚拟内存占用大小 单位:kb(killobytes)
  • RSS:实际内存占用大小 单位:kb(killobytes)
  • TTY:终端类型
  • STAT:进程状态
  • START:进程启动时刻
  • TIME:进程运行时长,进程已经消耗的CPU时间
  • COMMAND:启动进程的命令的名称和参数
1
2
3
$ ps -p 13870 -o vsz,rss
VSZ RSS
36274288 7766808
  • VSZ是指已分配的线性空间大小,这个大小通常并不等于程序实际用到的内存大小,产生这个的可能性很多,比如内存映射,共享的动态库,或者向系统申请了更多的堆,都会扩展线性空间大小。
  • RSS是Resident Set Size,常驻内存大小,即进程实际占用的物理内存大小

(3)jmap -heap指令

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
$ jmap -heap 13870

Attaching to process ID 13870, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.162-b12

using thread-local object allocation.
Parallel GC with 33 thread(s) parallel并发垃圾回收器

Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 8589934592 (8192.0MB) 堆最大内存
NewSize = 1431306240 (1365.0MB)
MaxNewSize = 2863136768 (2730.5MB)
OldSize = 2863661056 (2731.0MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB) 当前元空间大小
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB 元空间最大大小
G1HeapRegionSize = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
capacity = 1410334720 (1345.0MB)
used = 613113736 (584.710823059082MB)
free = 797220984 (760.289176940918MB)
43.472923647515394% used
From Space:
capacity = 10485760 (10.0MB)
used = 6048432 (5.7682342529296875MB)
free = 4437328 (4.2317657470703125MB)
57.682342529296875% used
To Space:
capacity = 10485760 (10.0MB)
used = 0 (0.0MB)
free = 10485760 (10.0MB)
0.0% used
PS Old Generation
capacity = 5417992192 (5167.0MB)
used = 325102840 (310.04222869873047MB)
free = 5092889352 (4856.9577713012695MB)
6.000430205123485% used

43895 interned Strings occupying 4216680 bytes.

大部分占用内存为free内存。

导出DUMP文件分析内存占用:

1
$ jmap -dump:format=b,file=xxx.dump 13870

(4)pmap指令

1
2
3
4
5
6
7
8
9
10
11
$ pmap -x 进程ID
Address Kbytes RSS Dirty Mode Mapping
0000000000400000 4 4 0 r-x-- java
0000000000600000 4 4 4 rw--- java
00000000017f8000 2256 2136 2136 rw--- [ anon ]
00000000c4000000 82944 63488 63488 rw--- [ anon ]
00000000c9100000 572416 0 0 ----- [ anon ]
00000000ec000000 27648 27136 27136 rw--- [ anon ]
00000000edb00000 300032 0 0 ----- [ anon ]
......
total kB 3701784 413924 400716
  • Address:内存分配地址
  • Kbytes:实际分配的内存大小
  • RSS:程序实际占用的内存大小
  • Mapping:分配该内存的模块的名称
  • anon:这些表示这块内存是由mmap分配的

(5)jstat指令

1
2
$ jstat -gc 16645| grep -v S0C | awk '{s=$3+$4+$6+$8+$10+$12} END {print s}'
1.77267e+06

堆内存(S0U+S1U+EU+OU)+元数据内存(MU)+已编译class占用内存(CSSU),单位KB。

JVM的几个GC堆和GC的情况,可以用jstat来监控,例如监控某个进程每隔1000毫秒刷新一次,输出20次

1
2
3
4
5
6
7
8
9
10
11
12
$ jstat -gcutil 进程ID 1000 20

S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 39.58 95.63 74.66 98.35 96.93 815 4.002 3 0.331 4.333
0.00 39.58 95.76 74.66 98.35 96.93 815 4.002 3 0.331 4.333
41.67 0.00 1.62 74.67 98.35 96.93 816 4.006 3 0.331 4.337
41.67 0.00 1.67 74.67 98.35 96.93 816 4.006 3 0.331 4.337
41.67 0.00 3.12 74.67 98.35 96.93 816 4.006 3 0.331 4.337
41.67 0.00 3.12 74.67 98.35 96.93 816 4.006 3 0.331 4.337
41.67 0.00 8.39 74.67 98.35 96.93 816 4.006 3 0.331 4.337
41.67 0.00 9.85 74.67 98.35 96.93 816 4.006 3 0.331 4.337

  • S0:年轻代中第一个survivor(幸存区)已使用的占当前容量百分比
  • S1:年轻代中第二个survivor(幸存区)已使用的占当前容量百分比
  • E:年轻代中Eden(伊甸园)已使用的占当前容量百分比
  • O:old代已使用的占当前容量百分比
  • P:perm代已使用的占当前容量百分比
  • YGC:从应用程序启动到采样时年轻代中gc次数
  • YGCT:从应用程序启动到采样时年轻代中gc所用时间(s)
  • FGC:从应用程序启动到采样时old代(全gc)gc次数
  • FGCT:从应用程序启动到采样时old代(全gc)gc所用时间(s)
  • GCT:从应用程序启动到采样时gc用的总时间(s)

(6)计算

  • JAVA进程内存 = JVM进程内存 + heap内存 + 永久代内存 + 本地方法栈内存 + 线程栈内存 + 堆外内存 + socket 缓冲区内存 + 元空间
  • linux内存和JAVA堆中的关系
    • RES = JAVA正在存活的内存对象大小 + 未回收的对象大小 + 其它
    • VIART= JAVA中申请的内存大小,即 -Xmx -Xms + 其它
    • 其它 = 永久代内存 + 本地方法栈内存 + 线程栈内存 + 堆外内存 + socket 缓冲区内存 + JVM进程内存

img

img

内存组成分别为:

  • JVM本身需要的内存,包括其加载的第三方库以及这些库分配的内存
  • NIO的DirectBuffer是分配的native memory
  • 内存映射文件,包括JVM加载的一些JAR和第三方库,以及程序内部用到的。上面 pmap 输出的内容里,有一些静态文件所占用的大小不在Java的heap里
  • JIT, JVM会将Class编译成native代码,这些内存也不会少,如果使用了Spring的AOP,CGLIB会生成更多的类,JIT的内存开销也会随之变大
  • JNI,一些JNI接口调用的native库也会分配一些内存,如果遇到JNI库的内存泄露,可以使用valgrind等内存泄露工具来检测
  • 线程栈,每个线程都会有自己的栈空间,如果线程一多,这个的开销就很明显

当前jvm线程数统计:

1
2
3
4
5
# (linux 64位系统中jvm线程默认栈大小为1MB)
$ jstack 进程ID |grep ‘tid’|wc -l
$ ps huH p 进程ID|wc -l ps -Lf 进程ID | wc -l
$ top -H -p 进程ID
$ cat /proc/{pid}/status

jmap/jstack 采样,频繁的采样也会增加内存占用,如果你有服务器健康监控,这个频率要控制一下

正常情况下jmap输出的内存占用远小于RSZ,可以不用太担心,除非发生一些严重错误,比如PermGen空间满了导致OutOfMemoryError发生,或者RSZ太高导致被OOM Killer给干掉,就得注意了。这几个内存指标之间的关系是:VSZ >> RSS >> Java程序实际使用的堆大小


参考:

🔗 《深入理解Java虚拟机》

🔗 《Java应用Top命令RES内存占用高分析