设为首页 加入收藏

TOP

JVM之ParNew和CMS日志分析(三)
2018-10-12 12:08:03 】 浏览:757
Tags:JVM ParNew CMS 日志 分析
与时钟时间,本质上,这里的 gc 线程会在 STW 之前做更多的工作,通常会持续 5s 左右;
  • [Times: user=11.93 sys=6.77, real=3.51 secs]:同前面。
  • 阶段5:Final Remark

    这是第二个 STW 阶段,也是 CMS 中的最后一个,这个阶段的目标是标记所有老年代所有的存活对象,由于之前的阶段是并发执行的,gc 线程可能跟不上应用程序的变化,为了完成标记老年代所有存活对象的目标,STW 就非常有必要了。

    通常 CMS 的 Final Remark 阶段会在年轻代尽可能干净的时候运行,目的是为了减少连续 STW 发生的可能性(年轻代存活对象过多的话,也会导致老年代涉及的存活对象会很多)。这个阶段会比前面的几个阶段更复杂一些,相关日志如下:

    2018-04-12T13:48:29.991+0800: 15581.906: [GC[YG occupancy: 1805641 K (3774912 K)]2018-04-12T13:48:29.991+0800: 15581.906: [GC2018-04-12T13:48:29.991+0800: 15581.906: [ParNew: 1805641K->48395K(3774912K), 0.0826620 secs] 8100493K->6348225K(24746432K), 0.0829480 secs] [Times: user=0.81 sys=0.00, real=0.09 secs]2018-04-12T13:48:30.074+0800: 15581.989: [Rescan (parallel) , 0.0429390 secs]2018-04-12T13:48:30.117+0800: 15582.032: [weak refs processing, 0.0027800 secs]2018-04-12T13:48:30.119+0800: 15582.035: [class unloading, 0.0033120 secs]2018-04-12T13:48:30.123+0800: 15582.038: [scrub symbol table, 0.0016780 secs]2018-04-12T13:48:30.124+0800: 15582.040: [scrub string table, 0.0004780 secs] [1 CMS-remark: 6299829K(20971520K)] 6348225K(24746432K), 0.1365130 secs] [Times: user=1.24 sys=0.00, real=0.14 secs]

    对上面的日志进行分析:

    1. YG occupancy: 1805641 K (3774912 K):年轻代当前占用量及容量,这里分别是 1.71G 和 3.6G;
    2. ParNew:...:触发了一次 young GC,这里触发的原因是为了减少年轻代的存活对象,尽量使年轻代更干净一些;
    3. [Rescan (parallel) , 0.0429390 secs]:这个 Rescan 是当应用暂停的情况下完成对所有存活对象的标记,这个阶段是并行处理的,这里花费了 0.0429390s;
    4. [weak

      refs processing, 0.0027800 secs]
      :第一个子阶段,它的工作是处理弱引用;
    5. [class unloading, 0.0033120 secs]:第二个子阶段,它的工作是:unloading the unused classes;
    6. [scrub symbol table, 0.0016780 secs] ... [scrub string table, 0.0004780 secs]:最后一个子阶段,它的目的是:cleaning up symbol and string tables which hold class-level metadata and internalized string respectively,时钟的暂停也包含在这里;
    7. 6299829K(20971520K):这个阶段之后,老年代的使用量与总量,这里分别是 6G 和 20G;
    8. 6348225K(24746432K):这个阶段之后,堆的使用量与总量(包括年轻代,年轻代在前面发生过 GC),这里分别是 6.05G 和 23.6G;
    9. 0.1365130 secs:这个阶段的持续时间;
    10. [Times: user=1.24 sys=0.00, real=0.14 secs]:对应的时间信息。

    经历过这五个阶段之后,老年代所有存活的对象都被标记过了,现在可以通过清除算法去清理那些老年代不再使用的对象。

    阶段6:Concurrent Sweep

    这里不需要 STW,它是与用户的应用程序并发运行,这个阶段是:清除那些不再使用的对象,回收它们的占用空间为将来使用。如下图所示(插图来自:GC Algorithms:Implementations —— Concurrent Mark and Sweep —— Full GC
    ):

    这个阶段对应的日志信息如下(这中间又发生了一次 Young GC):

    2018-04-12T13:48:30.128+0800: 15582.043: [CMS-concurrent-sweep-start]
    2018-04-12T13:48:36.638+0800: 15588.553: [GC2018-04-12T13:48:36.638+0800: 15588.554: [ParNew: 3403915K->52142K(3774912K), 0.0874610 secs] 4836483K->1489601K(24746432K), 0.0877490 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]

    分别介绍一下:

    1. CMS-concurrent-sweep:这个阶段主要是清除那些没有被标记的对象,回收它们的占用空间;
    2. 8.193/8.284 secs:这个阶段的持续时间与时钟时间;
    3. [Times: user=30.34 sys=16.44, real=8.28 secs]:同前面;

    阶段7:Concurrent Reset.

    这个阶段也是并发执行的,它会重设 CMS 内部的数据结构,为下次的 GC 做准备,对应的日志信息如下:

    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]

    日志详情分别如下:

    1. CMS-concurrent-reset:这个阶段的开始,目的如前面所述;
    2. 0.044/0.044 secs:这个阶段的持续时间与时钟时间;
    3. [Times: user=0.15 sys=0.10, real=0.04 secs]:同前面。

    总结

    CMS 通过将大量工
    编程开发网

    首页 上一页 1 2 3 4 下一页 尾页 3/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) }