JVM调优——之CMS GC日志分析

Posted 2020-09-05 干不好测试的程序员不是一个好工程师!

       最近在学习JVM和GC调优,今天总结下CMS的一些特点和要点,首先贴上一个实际的CMS GC log,先来解读下各个元素。

 

/*
  从下面的GC日志可以看出,当前最新版本(JDK1.8)中的CMS大致分为6步
  1. CMS Initial Mark 初始标记
  2. CMS-concurrent-mark 并发标记
  3. CMS-concurrent-preclean 预处理
  4. CMS-concurrent-abortable-preclean 预处理
  5. CMS Final Remark 重新标记
  6. CMS-concurrent-sweep 并发清除
  7. CMS-concurrent-reset 重置参数


 */

//初始标记 这个动作需要stop the world 这里只是标记一下GC Roots能直接关联到的对象
15887.169: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1307523K(1398144K)] 
1336024K(2027264K), 0.0046835 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

15887.173: [CMS-concurrent-mark-start]
15887.443: [CMS-concurrent-mark: 0.269/0.269 secs] [Times: user=0.90 sys=0.16, real=0.27 secs] 

15887.443: [CMS-concurrent-preclean-start]
15887.462: [CMS-concurrent-preclean: 0.019/0.020 secs] [Times: user=0.06 sys=0.02, real=0.02 secs] 

15887.463: [CMS-concurrent-abortable-preclean-start]
15888.433: [CMS-concurrent-abortable-preclean: 0.880/0.970 secs] [Times: user=3.00 sys=0.60, real=0.97 secs]

[GC (CMS Final Remark) [YG occupancy: 380362 K (629120 K)]15888.435: [Rescan (parallel) ,
0.1452201 secs]15888.580: [weak refs processing, 0.0015400 secs]
15888.582: [class unloading, 0.0541155 secs]
15888.636: [scrub symbol table, 0.0049675 secs]
15888.641: [scrub string table, 0.0009185 secs][1 CMS-remark: 1307523K(1398144K)]
1687886K(2027264K), 0.2161993 secs] [Times: user=0.62 sys=0.01, real=0.22 secs] 

15888.651: [CMS-concurrent-sweep-start]
15889.816: [CMS-concurrent-sweep: 0.947/1.165 secs] [Times: user=3.74 sys=0.68, real=1.17 secs] 

15889.816: [CMS-concurrent-reset-start]
15889.838: [CMS-concurrent-reset: 0.022/0.022 secs] [Times: user=0.07 sys=0.02, real=0.02 secs]