[ParNew 742993K->648506K(773376K), 0.1688876 secs]
[ParNew 753466K->659042K(773376K), 0.1695921 secs]
[CMS-initial-mark 661142K(773376K), 0.0861029 secs]
[Full GC 645986K->234335K(655360K), 8.9112629 secs]
[ParNew 339295K->247490K(773376K), 0.0230993 secs]
[ParNew 352450K->259959K(773376K), 0.1933945 secs]
下面是一个CMS开始的太早了的情况:
[ParNew 390868K->296358K(773376K), 0.1882258 secs][CMS-initial-mark 298458K(773376K), 0.0847541 secs]
[ParNew 401318K->306863K(773376K), 0.1933159 secs]
[CMS-concurrent-mark: 0.787/0.981 secs]
[CMS-concurrent-preclean: 0.149/0.152 secs]
[CMS-concurrent-abortable-preclean: 0.105/0.183 secs]
[CMS-remark 374049K(773376K), 0.0353394 secs]
[ParNew 407285K->312829K(773376K), 0.1969370 secs]
[ParNew 405554K->311100K(773376K), 0.1922082 secs]
[ParNew 404913K->310361K(773376K), 0.1909849 secs]
[ParNew 406005K->311878K(773376K), 0.2012884 secs]
[CMS-concurrent-sweep: 2.179/2.963 secs]
[CMS-concurrent-reset: 0.010/0.010 secs]
[ParNew 387767K->292925K(773376K), 0.1843175 secs]
[CMS-initial-mark 295026K(773376K), 0.0865858 secs]
[ParNew 397885K->303822K(773376K), 0.1995878 secs]
CMS-initial-mark表示CMS周期的开始, CMS-initial-sweep和CMS-concurrent-reset表示周期的结束。注意第一个CMS-initial-mark报告堆大小是298458K,然后注意,ParNew MinorGC报告在CMS-initial-mark和CMS-concurrent-reset之间只有很少的占用量变化,堆的占用量可以通过ParNew的->的右边的数值来表示。在这个例子中,CMS周期回收了很少的垃圾,通过在CMS-initial-mark和CMS-concurrent-reset之间只有很少的占用量变化可看出来。这里正确的做法是启动CMS周期用更大的old代空间占用率,通过使用参数
-XX:+UseCMSInitiatingOccupancyOnly和-XX:CMSInitiatingOccupancyFraction=<percent>。基于初始(CMS-initial-mark)占用量是298458K以及Java堆的大小是773376K,就是CMS发生的占用率是35%到40%(298458K/773376K=38.5%),可以使用选项来强制提高占用率的值。
下面是一个CMS周期回收了大量old代空间的例子,而且没有经历stop-the-world压缩垃圾回收,也就没有并发错误(concurrent mode failure)。同样的修改输出格式:
[ParNew 640710K->546360K(773376K), 0.1839508 secs]
[CMS-initial-mark 548460K(773376K), 0.0883685 secs]
[ParNew 651320K->556690K(773376K), 0.2052309 secs]
[CMS-concurrent-mark: 0.832/1.038 secs]
[CMS-concurrent-preclean: 0.146/0.151 secs]
[CMS-concurrent-abortable-preclean: 0.181/0.181 secs]
[CMS-remark 623877K(773376K), 0.0328863 secs]
[ParNew 655656K->561336K(773376K), 0.2088224 secs]
[ParNew 648882K->554390K(773376K), 0.2053158 secs]
[ParNew 489586K->395012K(773376K), 0.2050494 secs]
[ParNew 463096K->368901K(773376K), 0.2137257 secs]
[CMS-concurrent-sweep: 4.873/6.745 secs]
[CMS-concurrent-reset: 0.010/0.010 secs]
[ParNew 445124K->350518K(773376K), 0.1800791 secs]
[ParNew 455478K->361141K(773376K), 0.1849950 secs]
在这个例子中,在CMS周期开始的时候,CMS-initial-mark表明占用量是548460K。在CMS周期开始和结束(CMS-concurrent-reset)之间,ParNew MinorGC报告显著的减少了对象的占用量。尤其,在CMS-concurrent-sweep之前,占用量从561336K降低到了368901K。这个表明在CMS周期中,有190M空间被垃圾回收。需要注意的是,在CMS-concurrent-sweep之后的第一个ParNew MinorGC报告的占用量是350518K。这个说明超过190M被垃圾回收(561336K-350518K=210818K=205.88M)。
如果你决定优化CMS周期的启动,多尝试几个不同的old代占用率。监控垃圾回收信息以及分析这些信息可以帮助你做出正确的决定。
强制的垃圾回收 如果你想要观察通过调用System.gc()来启动的FullGC,当使用用CMS的时候,有两种方法来处理这种情况。
1、你可以请求HotSpot VM执行System.gc()的时候使用CMS周期,使用如下命令选项:
- -XX:+ExplicitGCInvokesConcurrent
- 或者
- -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses
第一个选项在Java 6及更新版本中能够使用,第二选项在从Java 6 Update 4之后才有。如果可以,建议使用后者。
2、你可以请求HotSpot VM选项忽视强制的调用System.gc(),可以使用如下选项:
这个选项用来让其他垃圾回收器忽略System.gc()请求。
当关闭的强制垃圾回收需要小心,这样做可能对Java性能产生很大的影响,关闭这个功能就像使用System.gc()一样需要明确的理由。
在垃圾回收日志里面找出明确的垃圾回收信息是非常容易的。垃圾回收的输出里面包含了一段文字来说明FullGC是用于调用System.gc().下面是一个例子:
2010-12-16T23:04:39.452-0600: [Full GC (System)
[CMS: 418061K->428608K(16384K), 0.2539726 secs]
418749K->4288608K(31168K),
[CMS Perm : 32428K->32428K(65536K)],0.2540393 secs]
[Times: user=0.12 sys=0.01, real=0.25 secs]
注意Full GC后面的(System)标签,这个说明是System.gc()引起的FullGC。如果你在垃圾回收日志里面观察到了明确的FullGC,想想为什么会出现、是否需要关闭、是否需要把应用源代码里面的相关代码删除掉,对CMS垃圾回收周期是否有意义。
并发的Permanent代垃圾回收
FullGC发生可能是由于permanent空间满了引起的,监控FullGC垃圾回收信息,然后观察Permanent代的占用量,判断FullGC是否是由于permanent区域满了引起的。下面是一个由于permanent代满了引起的FullGC的例子:
2010-12-16T17:14:32.533-0600: [Full GC
[CMS: 95401K->287072K(1048576K), 0.5317934 secs]
482111K->287072K(5190464K),
[CMS Perm : 65534K->58281K(65536K)], 0.5319635 secs]
[Times: user=0.53 sys=0.00, real=0.53 secs]
注意permanent代的空间占用量,通过CMS Perm :标签识别。permanent代空间大小是括号里面的值,65536K。在FullGC之前permanent代的占用量是->左边的值,65534K,FullGC之后的值是58281K。可以看到的是,在FullGC之前,permanent代的占用量以及基本上和permanent代的容量非常接近了,这个说明,FullGC是由Permanent代空间溢出导致的。同样需要注意的是,old代还没有到溢出空间的时候,而且没有证据说明CMS周期启动了。
HotSpot VM默认情况下,CMS不会垃圾回收permanent代空间,尽管垃圾回收日志里面有CMS Perm标签。为让CMS回收permanent代的空间,可以用过下面这个命令选项来做到:
- -XX:+CMSClassUnloadingEnabled
如果使用Java 6 update 3及之前的版本,你必须指定一个命令选项:
- -XX:+CMSPermGenSweepingEnabled
你可以控制permanent的空间占用率来启动CMS permanent代垃圾回收通过下面这个命令选项:
- -XX:CMSInitiatingPermOccupancyFraction=<percent>
这个参数的功能和-XX:CMSInitiatingOccupancyFraction很像,他指的是启动CMS周期的permanent代的占用率。这个参数同样需要和-XX:+CMSClassUnloadingEnabled配合使用。如果你想一直使用-XX:CMSInitiatingPermOccupancyFraction的值作为启动CMS周期的条件,你必须要指定另外一个选项:
- -XX:+UseCMSInitiatingOccupancyOnly
CMS暂停时间优化
在CMS周期里面,有两个阶段是stop-the-world阶段,这个阶段所有的应用线程都被阻塞了。这两阶段是“初始标记”阶段和“再标记”阶段,尽管初始标记解决是单线程的,但是通过不需要花费太长时间,至少比其他垃圾回收的时间短。再标记阶段是多线程的,线程数可通过命令选项来控制:
- -XX:ParallelGCThreads=<n>
在Java 6 update 23之后,默认值是通过Runtime.availableProcessors()来确定的,不过是建立在返回值小于等于8的情况下,反之,会使用Runtime.availableProcessors()*5/8作为线程数。如果有多个程序运行在同一个机器上面,建议使用比默认线程数更少的线程数。否则,垃圾回收可能会引起其他应用的性能下降,由于在同一个时刻,垃圾回收器使用太多的线程。
在某些情况下设置下面这个选项可以减少再标记的时间:
- -XX:+CMSScavengeBeforeRemark
这个选项强制HotSpot VM在FullGC之前执行MinorGC,在再标记步骤之前做MinorGC,可以减少再标记的工作量,由于减少了young代的对象数,这些对象能够在old代获取到的。
如果应用有大量的引用或者finalizable对象需要处理,指定下面这个选项可以减少垃圾回收的时间:
- -XX:+ParallelRefProcEnabled
这个选项可以用HotSpot VM的任何一种垃圾回收器上,他会是用多个的引用处理线程,而不是单个线程。这个选项不会启用多线程运行方法的finalizer。他会使用很多线程去发现需要排队通知的finalizable对象。
下一步
这一步结束,你需要看看应用的延迟需要是否满足了,无论是使用throughput垃圾回收器或者并发垃圾回收器。如果没有能够满足应用的需要,那么回头看看需求是否合理或者修改应用程序。如果满足了应用的需求,那么我们就进入下一步——优化吞吐量。