设为首页 加入收藏

TOP

JVM之ParNew和CMS日志分析(二)
2018-10-12 12:08:03 】 浏览:752
Tags:JVM ParNew CMS 日志 分析
90 secs] [Times: user=0.84 sys=0.00, real=0.09 secs] 2018-04-12T13:48:38.412+0800: 15590.327: [CMS-concurrent-sweep: 8.193/8.284 secs] [Times: user=30.34 sys=16.44, real=8.28 secs] 2018-04-12T13:48:38.419+0800: 15590.334: [CMS-concurrent-reset-start] 2018-04-12T13:48:38.462+0800: 15590.377: [CMS-concurrent-reset: 0.044/0.044 secs] [Times: user=0.15 sys=0.10, real=0.04 secs]

CMS Full GC 拆分开来,涉及的阶段比较多,下面分别来介绍各个阶段的情况。

阶段1:Initial Mark

这个是 CMS 两次 stop-the-wolrd 事件的其中一次,这个阶段的目标是:标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象,标记后示例如下所示(插图来自:GC Algorithms:Implementations —— Concurrent Mark and Sweep —— Full GC):

上述例子对应的日志信息为:

2018-04-12T13:48:26.233+0800: 15578.148: [GC [1 CMS-initial-mark: 6294851K(20971520K)] 6354687K(24746432K), 0.0466580 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

逐行介绍上面日志的含义:

  1. 2018-04-12T13:48:26.233+0800: 15578.148:GC 开始的时间,以及相对于 JVM 启动的相对时间(单位是秒,这里大概是4.33h),与前面 ParNew 类似,下面的分析中就直接跳过这个了;
  2. CMS-initial-mark:初始标记阶段,它会收集所有 GC Roots 以及其直接引用的对象;
  3. 6294851K:当前老年代使用的容量,这里是 6G;
  4. (20971520K):老年代可用的最大容量,这里是 20G;
  5. 6354687K:整个堆目前使用的容量,这里是 6.06G;
  6. (24746432K):堆可用的容量,这里是 23.6G;
  7. 0.0466580 secs:这个阶段的持续时间;
  8. [Times: user=

    0.04 sys=0.00, real=0.04 secs]
    :与前面的类似,这里是相应 user、system and real 的时间统计。

阶段2:并发标记

在这个阶段 Garbage Collector 会遍历老年代,然后标记所有存活的对象,它会根据上个阶段找到的 GC Roots 遍历查找。并发标记阶段,它会与用户的应用程序并发运行。并不是老年代所有的存活对象都会被标记,因为在标记期间用户的程序可能会改变一些引用,如下图所示(插图来自:GC Algorithms:Implementations —— Concurrent Mark and Sweep —— Full GC):

在上面的图中,与阶段1的图进行对比,就会发现有一个对象的引用已经发生了变化,这个阶段相应的日志信息如下:

2018-04-12T13:48:26.280+0800: 15578.195: [CMS-concurrent-mark-start]
2018-04-12T13:48:26.418+0800: 15578.333: [CMS-concurrent-mark: 0.138/0.138 secs] [Times: user=1.01 sys=0.21, real=0.14 secs]

这里详细对上面的日志解释,如下所示:

  1. CMS-concurrent-mark:并发收集阶段,这个阶段会遍历老年代,并标记所有存活的对象;
  2. 0.138/0.138 secs:这个阶段的持续时间与时钟时间;
  3. [Times: user=1.01 sys=0.21, real=0.14 secs]:如前面所示,但是这部的时间,其实意义不大,因为它是从并发标记的开始时间开始计算,这期间因为是并发进行,不仅仅包含 GC 线程的工作。

阶段3:Concurrent Preclean

Concurrent Preclean:这也是一个并发阶段,与应用的线程并发运行,并不会 stop 应用的线程。在并发运行的过程中,一些对象的引用可能会发生变化,但是这种情况发生时,JVM 会将包含这个对象的区域(Card)标记为 Dirty,这也就是 Card Marking。如下图所示(插图来自:GC Algorithms:Implementations —— Concurrent Mark and Sweep —— Full GC

在pre-clean阶段,那些能够从 Dirty 对象到达的对象也会被标记,这个标记做完之后,dirty card 标记就会被清除了,如下(插图来自:GC Algorithms:Implementations —— Concurrent Mark and Sweep —— Full GC

这个阶段相应的日志信息如下:

2018-04-12T13:48:26.418+0800: 15578.334: [CMS-concurrent-preclean-start]
2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-preclean: 0.056/0.057 secs] [Times: user=0.20 sys=0.12, real=0.06 secs]

其含义为:

  1. CMS-concurrent-preclean:Concurrent Preclean 阶段,对在前面并发标记阶段中引用发生变化的对象进行标记;
  2. 0.056/0.057 secs:这个阶段的持续时间与时钟时间;
  3. [Times: user=0.20 sys=0.12, real=0.06 secs]:同并发标记阶段中的含义。

阶段4:Concurrent Abortable Preclean

这也是一个并发阶段,但是同样不会影响影响用户的应用线程,这个阶段是为了尽量承担 STW(stop-the-world)中最终标记阶段的工作。这个阶段持续时间依赖于很多的因素,由于这个阶段是在重复做很多相同的工作,直接满足一些条件(比如:重复迭代的次数、完成的工作量或者时钟时间等)。这个阶段的日志信息如下:

2018-04-12T13:48:26.476+0800: 15578.391: [CMS-concurrent-abortable-preclean-start]
2018-04-12T13:48:29.989+0800: 15581.905: [CMS-concurrent-abortable-preclean: 3.506/3.514 secs] [Times: user=11.93 sys=6.77, real=3.51 secs]
  1. CMS-concurrent-abortable-preclean:Concurrent Abortable Preclean 阶段;
  2. 3.506/3.514 secs:这个阶段的持续时间
    编程开发网
首页 上一页 1 2 3 4 下一页 尾页 2/4/4
】【打印繁体】【投稿】【收藏】 【推荐】【举报】【评论】 【关闭】 【返回顶部
上一篇说说MQ之RocketMQ(二) 下一篇说说MQ之RocketMQ(一)

评论

帐  号: 密码: (新用户注册)
验 证 码:
表  情:
内  容:

array(4) { ["type"]=> int(8) ["message"]=> string(24) "Undefined variable: jobs" ["file"]=> string(32) "/mnt/wp/cppentry/do/bencandy.php" ["line"]=> int(217) }