设为首页 加入收藏

TOP

JVM之ParNew和CMS日志分析(一)
2018-10-12 12:08:03 】 浏览:20
Tags:JVM ParNew CMS 日志 分析

在两年前的文章 JVM 学习——垃圾收集器与内存分配策略中,已经对 GC 算法的原理以及常用的垃圾收集器做了相应的总结。今天这篇文章主要是对生产环境中(Java7)常用的两种垃圾收集器(ParNew:年轻代,CMS:老年代)从日志信息上进行分析,做一下总结,这样当我们在排查相应的问题时,看到 GC 的日志信息,不会再那么陌生,能清楚地知道这些日志是什么意思,GC 线程当前处在哪个阶段,正在做什么事情等。

ParNew 收集器

ParNew 收集器是年轻代常用的垃圾收集器,它采用的是复制算法,youngGC 时一个典型的日志信息如下所示:

2018-04-12T13:48:26.134+0800: 15578.050: [GC2018-04-12T13:48:26.135+0800: 15578.050: [ParNew: 3412467K->59681K(3774912K), 0.0971990 secs] 9702786K->6354533K(24746432K), 0.0974940 secs] [Times: user=0.95 sys=0.00, real=0.09 secs]

依次分析一下上面日志信息的含义:

  • 2018-04-12T13:48:26.134+0800:Mirror GC 发生的时间;
  • 15578.050:GC 开始时,相对 JVM 启动的相对时间,单位时秒,这里是4h+;
  • ParNew:收集器名称,这里是 ParNew 收集器,它使用的是并行的 mark-copy 算法,GC 过程也会 Stop the World;
  • 3412467K->59681K:收集前后年轻代的使用情况,这里是 3.25G->58.28M;
  • 3774912K:整个年轻代的容量,这里是 3.6G;
  • 0.0971990 secs:Duration for the collection w/o final cleanup.
  • 9702786K->6354533K:收集前后整个堆的使用情况,这里是 9.25G->6.06G;
  • 24746432K:整个堆的容量,这里是 23.6G;
  • 0.0974940 secs:ParNew 收集器标记和复制年轻代活着的对象所花费的时间(包括和老年代通信的开销、对象晋升到老年代开销、垃圾收集周期结束一些最后的清理对象等的花销);

对于 [Times: user=0.95 sys=0.00, real=0.09 secs],这里面涉及到三种时间类型,含义如下:

  • user:GC 线程在垃圾收集期间所使用的 CPU 总时间;
  • sys:系统调用或者等待系统事件花费的时间;
  • real:应用被暂停的时钟时间,由于 GC 线程是多线程的,导致了 real 小于 (user+real),如果是 gc 线程是单线程的话,real 是接近于 (user+real) 时间。

CMS 收集器

CMS 收集器是老年代经常使用的收集器,它采用的是标记-清楚算法,应用程序在发生一次 Full GC 时,典型的 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]
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]
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]
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]
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]
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.08774
编程开发网
首页 上一页 1 2 3 4 下一页 尾页 1/4/4
】【打印繁体】【投稿】【收藏】 【推荐】【举报】【评论】 【关闭】 【返回顶部
上一篇说说MQ之RocketMQ(二) 下一篇说说MQ之RocketMQ(一)

评论

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

最新文章

热门文章

C 语言

C++基础

windows编程基础

linux编程基础

C/C++面试题目