理解CMS GC日志

本文翻译自:
https://blogs.oracle.com/poonam/entry/understanding_cms_gc_logs

准备工作

JVM的GC日志的主要参数包括如下几个:
-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)
-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

CMS GC知识

CMS,全称Concurrent Mark and Sweep,用于对年老代进行回收,目标是尽量减少应用的暂停时间,减少full gc发生的机率,利用和应用程序线程并发的垃圾回收线程来标记清除年老代。
CMS并非没有暂停,而是用两次短暂停来替代串行标记整理算法的长暂停,内外的设置正常收集周期是这样的:

  1、CMS-initial-mark 初始标记
  2、CMS-concurrent-mark 并发标记的
  3、CMS-concurrent-preclean 执行预清理
  4、CMS-concurrent-abortable-preclean 执行可中止预清理
  5、CMS-remark 重新标记
  6、CMS-concurrent-sweep 并发清除
  7、CMS-concurrent-reset 并发重设状态等待下次CMS的触发

其中,CMS-initial-mark和CMS-remark会stop-the-world。

具体CMS的原理可以参看这篇文章
了解CMS(Concurrent Mark-Sweep)垃圾回收器

理解CMS GC日志

启动jvm的时候,增加参数-XX:+PrintGCDetails 和 -XX:+PrintGCTimeStamps可以打印出CMS GC的详细日志。读懂log信息有助于应用系统的各种参数调优,同时也有助于使得CMS实现更好的性能。

下面的例子使用了1.8的jvm

2016-12-21T15:05:30.175+0800: 90.439: [GC2016-12-21T15:05:30.175+0800: 90.439: [ParNew: 720896K->49062K(720896K), 0.2289360 secs] 864443K->262770K(1507328K), 0.2292340 secs] [Times: user=0.42 sys=0.00, real=0.23 secs]

Young generation(ParNew)收集。新生代的容量是720896K,在使用量达到了720896K时发生了GC,回收的Young generation容量为49062K。本次GC花费了0.2289360s

2016-12-21T15:05:14.628+0800: 74.892: [GC [1 CMS-initial-mark: 646746K(786432K)] 723228K(1507328K), 0.0456000 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

CMS开始回收tenured generation collection。这阶段是CMS初始化标记的阶段,从垃圾回收的“根对象”开始,且只扫描直接与“根对象”直接关联的对象,并做标记,在此期间,其他线程都会停止。

tenured generation的空间是786432K,在容量为646746K时开始执行初始标记。

2016-12-21T15:05:14.674+0800: 74.938: [CMS-concurrent-mark-start]

Concurrent marking(并发标记)阶段开始。
本阶段,其他线程重新开始正常执行,在上一步初始对象的基础上继续向下追溯标记

2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-mark: 0.513/0.514 secs] [Times: user=0.95 sys=0.05, real=0.52 secs] 并发标记阶段发费了0.513s cpu time 和0.514s 系统时间(包括其他线程占用cpu导致标记线程挂起的时间) 2016-12-21T15:05:15.188+0800: 75.452: [CMS-concurrent-preclean-start] concurrent-preclean(并发域清理)阶段开始 并发预清理阶段仍然是并发的。在这个阶段,虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从新生代晋升到老年代, 或者有一些对象被分配到老年代)。通过重新扫描,减少下一个阶段"重新标记"的工作,因为下一个阶段会Stop The World。 2016-12-21T15:05:15.192+0800: 75.456: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] concurrent-preclean花费了0.004s cpu time 和 0.004s 系统时间 2016-12-21T15:05:20.256+0800: 80.521: [GC[YG occupancy: 377234 K (720896 K)]2016-12-21T15:05:20.256+0800: 80.521: [Rescan (parallel) , 0.3789280 secs]2016-12-21T15:05:20.635+0800: 80.900: [weak refs processing, 0.0017780 secs]2016-12-21T15:05:20.637+0800: 80.901: [class unloading, 0.0141220 secs]2016-12-21T15:05:20.651+0800: 80.916: [scrub symbol table, 0.0259990 secs]2016-12-21T15:05:20.677+0800: 80.942: [scrub string table, 0.0024140 secs] [1 CMS-remark: 646746K(786432K)] 1023980K(1507328K), 0.4268320 secs] [Times: user=0.78 sys=0.01, real=0.42 secs] rescan阶段,会暂停其他线程。重新扫描CMS堆中剩余的对象,重新从“根对象”开始扫描,并且也会处理对象关联。本次扫描花费了 0.3789280s,其中弱引用对象(weak referene objects)处理大约用来0.0017780s,本阶段共计时间0.4268320s 2016-12-21T15:05:20.685+0800: 80.950: [CMS-concurrent-sweep-start] 开始清理没有标记的对象,清理阶段是和其他线程并发进行的。 2016-12-21T15:05:21.340+0800: 81.605: [CMS-concurrent-sweep: 0.640/0.655 secs] [Times: user=1.23 sys=0.03, real=0.66 secs] 时间,不解释了 2016-12-21T15:05:21.341+0800: 81.605: [CMS-concurrent-reset-start] 2016-12-21T15:05:21.402+0800: 81.666: [CMS-concurrent-reset: 0.061/0.061 secs] [Times: user=0.06 sys=0.05, real=0.06 secs] reset 阶段开始,并且输出所用时间。在这个阶段,与CMS相关数据结构被重新初始化,这样下一个周期可以正常进行。

以上过程是一个正常的CMS GC循环周期,接下来再分析一些不正常的日志

以下这个情况我没有复现,用的是文章的中数据,TODO之后想想能否打印出来这种情况

197.976: [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收集请求执行,但是没有成功。因为此时系统估计没有老生代中没有足够的空间去容纳这些对象(预测之后可能会出现老生代的空余空间将会被系统占光),我们称这种情况为 “full promotion guarantee failure”

在这种情况下下,并发式的CMS被阻塞了,full GC执行了,GC算法进入了concurrent mode failure状态,调用一个serail Old GC(阻塞了其他线程)来清理系统的Heap

日志显示,Full GC花费了2.3733725s,老生代空间由402978K降到了248977K

concurrent mode failure可以通过增大老生代的空间或者通过设置CMSInitiatingOccupancyFraction一个小的值使得CMS Collection发生的更频繁(CMSInitiatingOccupancyFraction可以控制CMS执行的时间,假设设置为70,说明老生代在利用率为70%时发生CMS),但是把这个值设置小也会导致CMS发生更加频繁。

某些情况下,promotion failures也会发生,即使是老生代有足够的空间。这个原因是"fragmentation"-老生代的可用空间不是连续的,而将新生代的对象移动到老生代需要连续的可用空间。而CMS是不会对内存进行压缩的算法,因此造成了这种问题。TODO,这篇文章解决了这个问题,我还没读

补充一下:concurrent mode failure产生的原理:CMS并发处理阶段用户线程还在运行中,伴随着程序运行会有新的垃圾产生,CMS无法处理掉它们(没有标记),只能在下一次GC的时候处理。同样的,用户线程运行就需要分配新的内存空间,为此,CMS收集器并不会在老年代全部被填满以后在进行收集,会预留一部分空间提供并发收集时的程序运行使用。即使是这样,还是会存在CMS运行期间预留的内存无法满足程序需求,就会出现"Concurrent Mode Failure"失败,这是,虚拟机将会启动备案操作:临时启动Serial Old 收集器来重新进行老年代的垃圾收集,Serial Old收集器会Stop the world,这样会导致停顿时间过长

同样的,CMS收集结束后会有大量的碎片空间差生,也会给大对象分配带来麻烦,往往会出现老年代还有很大空间剩余,但是无法找到足够多的连续空间来分配当前对象,不得不提前触发一次Full GC

197.976: [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]

这行GC日志显示的是一个请求失败的新生代GC处理。因为没有足够的空间来存储由新生代晋升上来的对象。这种现象称之为full promotioin guarantee failure 就此会在197.981处产生一次FULL GC,花费了 2.3733725秒 ,从而使CMS的空间从 402978K->248977K.

posted @ 2016-12-21 22:01  卡卡西sir  阅读(6043)  评论(2编辑  收藏  举报