为何在使用CMS gc算法时会出现连续两次full gc

现象:

jstat -gcutil pid 1000观察到的情况,段时间内连续两次full gc

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT 
59.33   0.00  63.98  69.66  59.31  24338  274.969   307   17.349  292.318
 59.33   0.00  86.19  69.66  59.31  24338  274.969   307   17.349  292.318
  0.00  60.52  10.22  70.10  59.31  24339  275.006   308   17.373  292.379
  0.00  60.52  30.03  70.10  59.31  24339  275.006   308   17.373  292.379
  0.00  60.52  53.57  70.10  59.31  24339  275.006   308   17.373  292.379
  0.00  60.52  76.45  70.10  59.31  24339  275.006   308   17.373  292.379
  0.00  60.52  93.77  70.10  59.31  24339  275.006   308   17.373  292.379
 61.16   0.00  15.66  70.53  59.31  24340  275.040   308   17.373  292.413
 61.16   0.00  40.71  67.96  59.31  24340  275.040   309   17.399  292.439
 61.16   0.00  66.44  59.90  59.31  24340  275.040   309   17.399  292.439

 同一时间的gc log

第一次

[GC [1 CMS-initial-mark: 1220647K(1740800K)] 1227199K(2385920K), 0.0057570 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

在旧生代空间为1220647K触发marking操作,后面1227199K(2385920K)=当前总体jvm内存使用(maxMem)

initial  标记从根集合中可直接访问的对象,要停顿整个应用

原文:This is initial Marking phase of CMS where all the objects directly reachable from roots are marked and this is done with all the mutator threads stopped.

[CMS-concurrent-mark: 1.084/1.084 secs] [Times: user=2.43 sys=0.11, real=1.08 secs]

完成mark耗时1.084 secs 并发执行

[CMS-concurrent-preclean: 0.008/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

开始执行清理,目的是减少remark的时间

 

第二次

[GC [ParNew: 579913K->4387K(645120K), 0.0080390 secs] 1800561K->1226923K(2385920K), 0.0082860 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

minor gc

  CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 2.715/5.047 secs] [Times: user=4.42 sys=0.40, real=5.05 secs]

停止执行preclean 默认是eden到达50%或者real time=5secs停止

[GC[YG occupancy: 153139 K (645120 K)][Rescan (parallel) , 0.0348570 secs][weak refs processing, 0.0005070 secs] [1 CMS-remark: 1222535K(1740800K)] 1375675K(2385920K), 0.0355150 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]

remark会停顿整个应用

[CMS-concurrent-sweep: 1.358/1.360 secs] [Times: user=1.85 sys=0.10, real=1.36 secs]

[CMS-concurrent-reset: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

gcutil 看到连续两次 full gc

原因分析:

目前来看,只有当initial-mark和remark时才会停顿整个应用,这个两个时间点jstat -gcutil表现都为full gc次数加一

 

real != user+sys

原因:user和sys代表处于用户和系统态的时间,不包含block的时间.但是由于多cpus这个东东是累加的.所以一般来说user和sys相加都大于real

real是从启动到终止的真实时间(现实中消耗),包含block.

----

CMS-initial-mark 对应一次fullgc,会停顿所有线程

CMS-remark 对应依次fullgc,会停顿所有线程

其他的日志对应的操作都是不会停顿线程的

可以通过grep "initial" 和grep "remark" 来看你每次停顿的时间