1.开启垃圾回收日志
在运行一个java程序时可以在命令行中加入相应的JVM垃圾回收参数,获取程序运行时详细的垃圾回收日志信息。以下是一些大概的参数:
-XX:+PrintGC与-verbose:gc 这两个命令效果都是一样,打印最基本的回收信息
-XX:+PrintGCDetails 可以打印详细GC信息至控制台
-XX:+PrintGCDateStamps 可以记录GC发生的详细时间
-Xloggc:{log.dir} 可以把GC输出至文件,这对长时间服务器GC监控
最常见的几种垃圾回收参数莫过于以上几种了,但是并不是全部,仍然有一些进阶的垃圾回收参数,比如如下:
-XX:+PrintHeapAtGC 开关了解堆的更全面的信息
-XX:+PrintGCApplicationConcurrentTime 输出应用程序的执行时间
-XX:+PrintGCApplicationStoppedTime 输出GC造成应用暂停的时间
-XX:+PrintReferenceGC 用来跟踪系统内的(softReference)软引用,(weadReference)弱引用,(phantomReference)虚引用,显示引用过程。弱引用,软引用及虚引用对GC的影响
-verbose:class 跟踪类的加载和卸载,亦可单独配置-XX:+TraceClassLoading跟踪类的加载或单独配置-XX:+TraceClassUnloading
-XX:+PrintVMOptions 打印出JVM接受到的显式(主动配置的)命令行参数
-XX:+PrintCommandLineFlags 打印出显式(主动配置)和隐式(JVM自行设置)的一些参数,其中显式即等同于-XX:+PrintVMOptions参数设置
-XX:+PrintClassHistogram 打印出Java各类实例的数量以及空间大小
以上均是一些JVM参数,大部分可以组合使用,至于其详细的使用及详细涵义,可自行搜索查阅。本文主要是分析GC的回收日志,故本文采取的是组合-XX:+PrintGCDetails -Xloggc:{log.file}这两条命令,即下文中分析的日志是基于此命令组合产生的,存在于log.file文件中,此文中采取的应用程序命令如下。
/usr/jdk64/jdk1.7.0_67/bin/java -XX:NewRatio=3 -XX:+UseConcMarkSweepGC -XX:-UseGCOverheadLimit -XX:CMSInitiatingOccupancyFraction=70 -XX:+PrintGCDetails -Xloggc:/var/lib/ambari-server/gc.log -Xms8048m -Xmx16384m Application
1
以上命令采用的ConcMarkSweepGC垃圾回收器,指定此回收器,新生才使用ParNew回收器,老年代使用CMS。-XX:CMSInitiatingOccupancyFraction指定老年代空间使用率达到多少时,进行一次CMS垃圾回收。-XX:NewRatio提供年老代和年轻代的比例大小。默认值是2。详细的垃圾回收器分类与指定,会在其下文中进行介绍,在此就不多作叙述。
2.垃圾回收日志分析
下图是摘录的GC日志示例图。
如上文看到的第一行,最前面是虚拟机启动的时间,即运行了523.006秒时产生的垃圾回收。ParNew代表新生代容量为1854272K,括号中的数值。GC回收后占用从165011K降到133039k,耗时0.0305160秒。后面紧跟着的是整个堆内存的回收情况,堆内存从当前4193343k降到4161371k的大小,同理后面括号中指定的是整个堆内存的大小(8035712k),后面3个时间分别是三类回收时间,用户,系统,以及实际时间,一般只需要看real的时间就够了,这个只是新生代的回收,可以比对下,新生的回收的内存是165011K-133039k=31972k,这个和实际的堆回收的内存4193343k-4161371k=31972k是保持一致的。不过也有细心的读者发现,整个堆内存的大小是8035712k与命令行中指定的8048m的堆内存大小不一致,这是什么原因呢?
在这里猜测下,实际的堆内存还包含持久代的,一般说堆的持久代就是说方法区,因为一旦JVM把方法区(类信息,常量池,静态字段,方法)加载进内存以后,这些内存一般是不会被回收的了。持久代内存指定通过-XX:PermSize–默认是物理内存的1/64以及-XX:MaxPermSize指定–默认是物理内存的1/4。关于,方法区是否属于堆内存的讨论好像一直未停,很多人说持久代属于非堆,也有人说方法区物理上存在于堆里,而且是在堆的持久代里面;但在逻辑上,方法区和堆是独立的,在此姑且就认为日志中少掉的部分堆内存是持久代占用了吧。
再往下可以看到,在经历多次新生代内存回收之后,有一部分关于CMS的内存回收标记。
在虚拟机运行536.547秒时开始使用CMS回收器进行老年代回收。
第一步是初始标记(CMS-initial-mark)阶段,这个阶段标记由根可以直接到达的对象,标记期间整个应用线程会暂停。此时老年代容量为6181440K,括号中的数值,CMS 回收器在空间占用达到 4403864k时被触发,这里可以计算下:4403864/6181440=71.24%,已经超过上文配置的70%的回收阈值,故针对年老代进行垃圾回收。后面紧跟的当前堆内存的大小4611534k以及括号中是整个堆内存的大小8035712k。
第二步是 [CMS-concurrent-mark-start]开始并发标记(concurrent-mark-start) 阶段,在第一个阶段被暂停的线程重新开始运行,由前阶段标记过的对象出发,所有可到达的对象都在本阶段中标记。 [CMS-concurrent-mark: 0.356/0.356 secs]
代表并发标记阶段结束,占用 0.356秒CPU时间,0.356秒墙钟时间(也包含线程让出CPU给其他线程执行的时间)
第三步是[CMS-concurrent-preclean-start]开始预清理阶段
预清理也是一个并发执行的阶段。因为标记和应用线程是并发执行的,因此会有些对象的状态在标记后会改变,此阶段正是解决这个问题。因为之后的Rescan阶段也会stop the world,为了使暂停的时间尽可能的小,也需要preclean阶段先做一部分工作以节省时间。
第四步是CMS-concurrent-abortable-preclean阶段,加入此阶段的目的是使cms gc更加可控一些,作用也是执行一些预清理,以减少Rescan阶段造成应用暂停的时间。
第五步则是Rescan阶段,Stop-the-world 阶段,从根及被其引用对象开始,重新扫描 CMS 堆中残留的更新过的对象。这里重新扫描费时0.0351330秒,处理弱引用对象费时0.0008150秒。后面是重新remark的信息,具体参见第一步,本步骤费时0.037 秒,该阶段总体耗时0.04秒。
第六步是[CMS-concurrent-sweep-start]阶段,开始并发清理阶段,在清理阶段,应用线程还在运行。紧接着并发清理完成时间。
最后一步则是[CMS-concurrent-reset-start]开始并发重置,该阶段主要重新初始化CMS内部数据结构,以备下一轮 GC 使用,紧接着是该阶段的完成时间。
如上就是一个正常的CMS垃圾回收过程,其中可以看到,整个CMS期间还夹杂着2条新生代内存的回收过程也属于正常。同样还有不正常的CMS垃圾回收日志,比如:
[GC 197.976: [ParNew: 260872K->260872K(261952K), 0.0000688 secs]197.976: [CMS197.981: [CMS-concurrent-sweep: 0.516/0.531 secs]
(concurrent mode failure): 402978K->248977K(786432K), 2.3728734 secs] 663850K->248977K(1048384K), 2.3733725 secs]
这段信息显示ParNew 收集器被请求进行新生代的回收,但收集器并没有尝试回收,因为它预计在最糟糕的情况下,CMS老年代中没有足够的空间容纳新生代的幸存对象。我们把这个失败称之为”完全晋升担保失败”。因为这样,并发模式的CMS被中断同并且在 197.981秒时,Full GC被启动。这次Full GC,采用标记-清除-整理算法,会发生stop-the-world费时2.3733725秒。CMS 老年代占用从 402978K 降到248977K。为避免并发模式失败, 通过增加老年代空间大小或者设置参数 CMSInitiatingOccupancyFraction 同时设置UseCMSInitiatingOccupancyOnly为true。参数 CMSInitiatingOccupancyFraction 的值必须谨慎选择,设置过低会造成频繁发生 CMS 回收。
有时我们发现,当日志中出现晋升失败时,老年代还有足够的空间。这是因为”碎片”,老年代中的可用空间并不连续,而从新生代晋升上来的对象,需要一块连续的可用空间。CMS 收集器是一种非压缩收集器,在某种类型的应用中会发生碎片。