Garbage Collector: CMS abort preclean issue?

Question

I am having issue with Heap memory. Everyday memory increases by 100MB and keep on increases and FULL GC ran after the limit of 1.5GB, but still it didn't recovering. after checking the logs, seeing the CMS:abort preclean? iS this can be the factor. any help is appreciated.

CMS:abort preclean due to time?? any idea how to resolve this?

Enviornment:Java 1.6

Here are my GC params:


-Dfile.encoding=UTF-8 \
  -Duser.timezone=US/Eastern \
  -Dsun.net.inetaddr.ttl=60 \
  -Dsun.net.inetaddr.negative.ttl=60 \
  -Xms1024m \
  -Xmx1536m \
  -Xss512k \
  -verbose:gc  \
  -Xloggc:$CATALINA_BASE/logs/gc_log \
  -XX:+DisableExplicitGC \
  -XX:+HeapDumpOnOutOfMemoryError \
  -XX:+PrintGCDetails \
  -XX:+PrintGCTimeStamps \
  -XX:+UseConcMarkSweepGC \
  -XX:+UseParNewGC \
  -XX:CMSInitiatingOccupancyFraction=50 \
  -XX:GCTimeRatio=99 \
  -XX:MaxNewSize=512m \
  -XX:MaxTenuringThreshold=30 \
  -XX:NewSize=512m \
  -XX:SurvivorRatio=6 \
  -XX:TargetSurvivorRatio=90 \

**495747.455: [CMS-concurrent-mark-start]
495749.159: [CMS-concurrent-mark: 1.705/1.705 secs] [Times: user=1.91 sys=0.05, real=1.71 secs] 
495749.159: [CMS-concurrent-preclean-start]
495749.166: [CMS-concurrent-preclean: 0.006/0.007 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
495749.166: [CMS-concurrent-abortable-preclean-start]
495752.728: [GC 495752.728: [ParNew: 432226K->29458K(458752K), 0.0462900 secs] 1419590K->1016821K(1507328K), 0.0464200 secs] [Times: user=0.08 sys=0.00, real=0.04 secs] 
 CMS: abort preclean due to time 495754.230: [CMS-concurrent-abortable-preclean: 2.067/5.063 secs] [Times: user=2.43 sys=0.11, real=5.06 secs] 
495754.230: [GC[YG occupancy: 146431 K (458752 K)]495754.230: [Rescan (parallel) , 0.0446310 secs]495754.275: [weak refs processing, 0.0000080 secs] [1 CMS-remark: 987363K(1048576K)] 1133794K(1507328K), 0.0447400 secs] [Times: user=0.07 sys=0.00, real=0.05 secs]**

Aditya · Answer 1 · 2019-12-09T07:22:14.930

Looks like a duplicate of this question

I think the problem is with 2 parameters

-XX:CMSInitiatingOccupancyFraction=50

A concurrent collection is invoked if the occupancy of the Tenured generation exceeds this value. It might be the occupancy is consistently over 50% which is invoking the collections repeatedly, leading to a full GC. (The default of this is 68%)

-XX:GCTimeRatio=99

The error might be because of this parameter, as the GC time ratio is 1% and the preclean phase has taken ~2 seconds out of 5 seconds, so the preclean might have been aborted due to a time out. (I think the default is 5%)

Increasing the Xmx should solve the issue, but I agree with Peter Lawrey that you shouldn't be tuning the JVM so much unless you are very sure of how the flags affect the working. Also do read this link on GC tuning

score 2 · Answer 2 · answered Nov 15 '11 at 14:22

2

The abortable pre-clean is abortable. It could be a problem, but I suspect the least of your worries.

If memory is not being cleaned up after a Full GC is it because this memory is being retained somewhere. I would do a heap dump to see why this memory is being retained. i.e. there are resources you are holding onto.

While you are investigating that I would try increasing the memory available. e.g. a New size of 2 GB and a tenured space of 2 GB. A larger young generation size will decrease the number of objects getting into the tenured space and needing to be cleaned up later.

I wouldn't try to tune so many parameters as the JVM can configure itself fairly efficiently.

answered Nov 15 '11 at 14:22

Peter Lawrey

525,659
79
751
1,130

I tried with 2GB, but after reaching the limit:(concurrent mode failure): 1048575K->1048296K(1048576K), 5.4770550 secs] 1506365K->1244278K(1507328K), [CMS Perm : 43867K->43862K(76736K)], 5.4773220 secs] [Times: user=5.40 sys=0.02, real=5.46 secs] 498938.770: [Full GC 498938.770: [CMS: 1048442K->1048251K(1048576K), 4.5968810 secs] 1507194K->1252719K(1507328K), [CMS Perm : 43870K->43866K(76736K)], 4.5971510 secs] [Times: user=4.56 sys=0.01, real=4.61 secs] 498943.375: [GC [1 CMS-initial-mark: 1048251K(1048576K)] 1255332K(1507328K), 1.1042510 secs] [Times: user=1.10 sys=0.01, real=1.10 secs] – Dhanu Nov 15 '11 at 14:58
AFAIK, This happens when you are promoting objects faster than it can clean them up. How big was the young space? – Peter Lawrey Nov 15 '11 at 16:30
-XX:MaxNewSize=512m \ this contributes to young space. – Dhanu Nov 15 '11 at 17:10

Garbage Collector: CMS abort preclean issue?

2 Answers2