Fork me on GitHub

CMS 日志

https://www.cnblogs.com/onmyway20xx/p/6590603.html

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
https://www.cnblogs.com/redcreen/archive/2011/05/04/2037057.html
-Xms:表示java虚拟机堆区内存初始内存分配的大小,通常为操作系统可用内存的1/64大小即可,但仍需按照实际情况进行分配。
-Xmx:表示java虚拟机堆区内存可被分配的最大上限,通常为操作系统可用内存的1/4大小。
-Xmn:至于这个参数则是对 -XX:newSize、-XX:MaxnewSize两个参数的同时配置
Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for linux-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:40 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 131454000k(14740160k free), swap 0k(0k free)
CommandLine flags: -XX:CMSFullGCsBeforeCompaction=1 -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:+CMSScavengeBeforeRemark -XX:ErrorFile=worker_errorfile.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath==worker.hprof -XX:InitialHeapSize=4294967296 -XX:MaxHeapSize=19973275648 -XX:MaxNewSize=4294967296 -XX:MaxTenuringThreshold=6 -XX:NewSize=4294967296 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCMSCompactAtFullCollection -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
2019-08-17T10:07:07.759+0800: 6.103: [GC (Allocation Failure) 2019-08-17T10:07:07.760+0800: 6.103: [ParNew: 3355456K->152609K(3774848K), 0.0598612 secs] 3355456K->152609K(3774912K), 0.0600314 secs] [Times: user=0.08 sys=1.05, real=0.06 secs]
2019-08-17T10:07:11.819+0800: 10.162: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(64K)] 2918904K(3774912K), 0.1643878 secs] [Times: user=3.16 sys=0.00, real=0.17 secs]
2019-08-17T10:07:11.983+0800: 10.326: [CMS-concurrent-mark-start]
2019-08-17T10:07:11.986+0800: 10.329: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
2019-08-17T10:07:11.986+0800: 10.329: [CMS-concurrent-preclean-start]
2019-08-17T10:07:11.988+0800: 10.331: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2019-08-17T10:07:11.988+0800: 10.331: [CMS-concurrent-abortable-preclean-start]
2019-08-17T10:07:12.368+0800: 10.711: [GC (Allocation Failure) 2019-08-17T10:07:12.368+0800: 10.712: [ParNew: 3508065K->336875K(3774848K), 0.0346936 secs] 3508065K->336875K(3774912K), 0.0348346 secs] [Times: user=0.17 sys=0.66, real=0.04 secs]
2019-08-17T10:07:14.123+0800: 12.466: [CMS-concurrent-abortable-preclean: 1.162/2.135 secs] [Times: user=6.01 sys=0.91, real=2.14 secs]
2019-08-17T10:07:14.124+0800: 12.467: [GC (CMS Final Remark) [YG occupancy: 2144845 K (3774848 K)]2019-08-17T10:07:14.124+0800: 12.467: [GC (CMS Final Remark) 2019-08-17T10:07:14.124+0800: 12.467: [ParNew: 2144845K->419392K(3774848K), 0.1924931 secs] 2144845K->564906K(3950016K), 0.1925920 secs] [Times: user=0.43 sys=0.35, real=0.19 secs]
2019-08-17T10:07:14.316+0800: 12.659: [Rescan (parallel) , 0.0021755 secs]2019-08-17T10:07:14.318+0800: 12.662: [weak refs processing, 0.0000831 secs]2019-08-17T10:07:14.319+0800: 12.662: [class unloading, 0.0045748 secs]2019-08-17T10:07:14.323+0800: 12.666: [scrub symbol table, 0.0022006 secs]2019-08-17T10:07:14.325+0800: 12.668: [scrub string table, 0.0005412 secs][1 CMS-remark: 145514K(175168K)] 564906K(3950016K), 0.2031034 secs] [Times: user=0.49 sys=0.35, real=0.20 secs]
2019-08-17T10:07:14.327+0800: 12.670: [CMS-concurrent-sweep-start]
2019-08-17T10:07:14.327+0800: 12.670: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2019-08-17T10:07:14.327+0800: 12.670: [CMS-concurrent-reset-start]
2019-08-17T10:07:14.450+0800: 12.793: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.12 sys=0.13, real=0.13 secs]

Minor GC

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
2019-08-17T10:07:14.124+0800: 12.467: [ParNew: 2144845K->419392K(3774848K), 0.1924931 secs] 2144845K->564906K(3950016K), 0.1925920 secs] [Times: user=0.43 sys=0.35, real=0.19 secs]
2019-08-17T10:07:12.368+0800: 10.711: [GC (Allocation Failure) 2019-08-17T10:07:12.368+0800: 10.712: [ParNew: 3508065K->336875K(3774848K), 0.0346936 secs] 3508065K->336875K(3774912K), 0.0348346 secs] [Times: user=0.17 sys=0.66, real=0.04 secs]
2019-08-17T10:07:12.368+0800: GC发生的时间;
10.711: GC开始,相对JVM启动的相对时间,单位是秒;
GC: 区别MinorGC和FullGC的标识,这次代表的是MinorGC;
Allocation Failure: MinorGC的原因,在这个case里边,由于年轻代不满足申请的空间,因此触发了MinorGC;
ParNew: 收集器的名称,它预示了年轻代使用一个并行的 mark-copy stop-the-world 垃圾收集器;
3508065K->336875K(3774848K) – 收集前后年轻代的使用情况;(整个年轻代的容量);
3508065K->336875K(3774912K) – 收集前后整个堆的使用情况;(整个堆的容量);
0.1021309 secs – ParNew收集器标记和复制年轻代活着的对象所花费的时间(包括和老年代通信的开销、对象晋升到老年代时间、垃圾收集周期结束一些最后的清理对象等的花销);
[Times: user=0.78 sys=0.01, real=0.11 secs] – GC事件在不同维度的耗时,具体的用英文解释起来更加合理:
user – Total CPU time that was consumed by Garbage Collector threads during this collection
sys – Time spent in OS calls or waiting for system event
real – Clock time for which your application was stopped. With Parallel GC this number should be close to (user time + system time) divided by the number of threads used by the Garbage Collector. In this particular case 8 threads were used. Note that due to some activities not being parallelizable, it always exceeds the ratio by a certain amount.
开始的时候:整个堆的大小是 3508065K,年轻代大小是3508065K,这说明老年代大小是 3508065-3508065=0K,
收集完成之后:整个堆的大小是 336875K,年轻代大小是336875K,这说明老年代大小是 336875-336875=0K,
老年代的大小增加了:0-0=0 年轻代到年老代promot了0K的数据;

Full/Major GC

1.Initial Mark

  这是CMS中两次stop-the-world事件中的一次。
  它有两个目标:一是标记老年代中所有的GC Roots;二是标记被年轻代中活着的对象引用的对象。
标记结果如下:

1
2
3
4
5
6
2019-08-17T10:07:11.819+0800: 10.162: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(64K)] 2918904K(3774912K), 0.1643878 secs] [Times: user=3.16 sys=0.00, real=0.17 secs]
2019-08-17T10:07:11.819+0800: 10.162 – GC事件开始,包括时钟时间和相对JVM启动时候的相对时间,下边所有的阶段改时间的含义相同;
CMS Initial Mark – 收集阶段,开始收集所有的GC Roots和直接引用到的对象;
0K(64K) – 当前老年代使用情况(老年代可用容量);
2918904K(3774912K) – 当前整个堆的使用情况(整个堆的容量);

2.Concurrent Mark

  这个阶段会遍历整个老年代并且标记所有存活的对象,从“初始化标记”阶段找到的GC Roots开始。
  并发标记的特点是和应用程序线程同时运行。并不是老年代的所有存活对象都会被标记,因为标记的同时应用程序会改变一些对象的引用等。
标记结果如下:在图中,一个引用的箭头已经远离了当前对象(current obj)

1
2
3
4
5
6
2019-08-17T10:07:11.983+0800: 10.326: [CMS-concurrent-mark-start]
2019-08-17T10:07:11.986+0800: 10.329: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
CMS-concurrent-mark – 并发收集阶段,这个阶段会遍历整个年老代并且标记活着的对象;
0.003/0.003 secs – 展示该阶段持续的时间和时钟时间;
[Times: user=0.07 sys=0.00, real=0.03 secs] – 同上

3.Concurrent Preclean

  这个阶段又是一个并发阶段,和应用线程并行运行,不会中断他们。前一个阶段在并行运行的时候,一些对象的引用已经发生了变化,当这些引用发生变化的时候,JVM会标记堆的这个区域为Dirty Card(包含被标记但是改变了的对象,被认为”dirty”),这就是 Card Marking。

  在pre-clean阶段,那些能够从dirty card对象到达的对象也会被标记,这个标记做完之后,dirty card标记就会被清除了,如下:

  另外,一些必要的清扫工作也会做,还会做一些final remark阶段需要的准备工作;

1
2
3
4
5
2019-08-17T10:07:11.986+0800: 10.329: [CMS-concurrent-preclean-start]
2019-08-17T10:07:11.988+0800: 10.331: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
CMS-concurrent-preclean – 这个阶段负责前一个阶段标记了又发生改变的对象标记;
0.016/0.016 secs – 展示该阶段持续的时间和时钟时间;
[Times: user=0.02 sys=0.00, real=0.02 secs] – 同上

4.Concurrent Abortable Preclean

  又一个并发阶段不会停止应用程序线程。这个阶段尝试着去承担STW的Final   Remark阶段足够多的工作。这个阶段持续的时间依赖好多的因素,由于这个阶段是重复的做相同的事情直到发生aboart的条件(比如:重复的次数、多少量的工作、持续的时间等等)之一才会停止。

1
2
3
4
5
6
7
8
2019-08-17T10:07:11.988+0800: 10.331: [CMS-concurrent-abortable-preclean-start]
2019-08-17T10:07:14.123+0800: 12.466: [CMS-concurrent-abortable-preclean: 1.162/2.135 secs] [Times: user=6.01 sys=0.91, real=2.14 secs]
CMS-concurrent-abortable-preclean – 可终止的并发预清理;
0.167/1.074 secs – 展示该阶段持续的时间和时钟时间;
[Times: user=0.20 sys=0.00, real=1.07 secs] – 同上
这个阶段很大程度的影响着即将来临的Final Remark的停顿,有相当一部分重要的 configuration options 和 失败的模式;

5.Final Remark

  这个阶段是CMS中第二个并且是最后一个STW的阶段。该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的,它可能跟不上应用程序改变的速度,这个时候,STW是非常需要的来完成这个严酷考验的阶段。
  通常CMS尽量运行Final Remark阶段在年轻代是足够干净的时候,目的是消除紧接着的连续的几个STW阶段。
分析:

1
2
3
4
5
6
7
8
9
10
11
12
2019-08-17T10:07:14.124+0800: 12.467: [ParNew: 2144845K->419392K(3774848K), 0.1924931 secs] 2144845K->564906K(3950016K), 0.1925920 secs] [Times: user=0.43 sys=0.35, real=0.19 secs]
2019-08-17T10:07:14.316+0800: 12.659: [Rescan (parallel) , 0.0021755 secs]2019-08-17T10:07:14.318+0800: 12.662: [weak refs processing, 0.0000831 secs]2019-08-17T10:07:14.319+0800: 12.662: [class unloading, 0.0045748 secs]2019-08-17T10:07:14.323+0800: 12.666: [scrub symbol table, 0.0022006 secs]2019-08-17T10:07:14.325+0800: 12.668: [scrub string table, 0.0005412 secs][1 CMS-remark: 145514K(175168K)] 564906K(3950016K), 0.2031034 secs] [Times: user=0.49 sys=0.35, real=0.20 secs]
1.CMS Final Remark – 收集阶段,这个阶段会标记老年代全部的存活对象,包括那些在并发标记阶段更改的或者新创建的引用对象;
2.YG occupancy: 387920 K (613440 K) – 年轻代当前占用情况和容量;
3.[Rescan (parallel) , 0.0085125 secs] – 这个阶段在应用停止的阶段完成存活对象的标记工作;
4.weak refs processing, 0.0000243 secs]65.559 – 第一个子阶段,随着这个阶段的进行处理弱引用;
5.class unloading, 0.0013120 secs]65.560 – 第二个子阶段(that is unloading the unused classes, with the duration and timestamp of the phase);
6.scrub string table, 0.0001759 secs – 最后一个子阶段(that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively)
7.10812086K(11901376K) – 在这个阶段之后老年代占有的内存大小和老年代的容量;
8.11200006K(12514816K) – 在这个阶段之后整个堆的内存大小和整个堆的容量;

通过以上5个阶段的标记,老年代所有存活的对象已经被标记并且现在要通过Garbage Collector采用清扫的方式回收那些不能用的对象了。

6.Concurrent Sweep

  和应用线程同时进行,不需要STW。这个阶段的目的就是移除那些不用的对象,回收他们占用的空间并且为将来使用。
如图:

1
2
3
4
2019-08-17T10:07:14.327+0800: 12.670: [CMS-concurrent-sweep-start]
2019-08-17T10:07:14.327+0800: 12.670: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
CMS-concurrent-sweep – 这个阶段主要是清除那些没有标记的对象并且回收空间;

7.Concurrent Reset

这个阶段并发执行,重新设置CMS算法内部的数据结构,准备下一个CMS生命周期的使用。

1
2
3
4
2019-08-17T10:07:14.327+0800: 12.670: [CMS-concurrent-reset-start]
2019-08-17T10:07:14.450+0800: 12.793: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.12 sys=0.13, real=0.13 secs]
CMS-concurrent-reset – 这个阶段重新设置CMS算法内部的数据结构,为下一个收集阶段做准备;

-----------------本文结束,感谢您的阅读-----------------