repeated java garbage collection even though there is enough java memory- why

Question

Our java process is eating up lot of CPU and the log shows its doing GC too often even though used memory is ~5GB (taken from JMX console) and the Min and Max mem is 10GB.

our JVM args is : JVM_GC="-verbose:gc -Xnoclassgc -XX:+PrintGCDetails -XX:+UseParNewGC -XX:NewSize=3GB -XX:ParallelGCThreads=8 -XX:MaxTenuringThreshold=15 -XX:+UseConcMarkSweepGC"

and MinHeap=MaxHeap=10GB

any idea what might be triggering GC? and why is it happening to often and too soon? We cant connect any sort of profiling tool as its production box apart from getting some settings via JMX... Thanks ..... GC log ....

@2011-07-20 02:10:46
[Full GC (System) [CMS: 3333423K->4019122K(7340032K), 13.4979250 secs] 4876606K->4019122K(10171200K), [CMS Perm : 21656K->21608K(21824K)], 13.4980930 sec s] [Times: user=12.99 sys=0.50, real=13.50 secs]
[GC [1 CMS-initial-mark: 4019122K(7340032K)] 4041525K(10171200K), 0.0009110 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
@2011-07-20 02:11:10
[CMS-concurrent-mark: 10.322/10.753 secs] [Times: user=21.55 sys=0.22, real=10.75 secs]
[CMS-concurrent-preclean: 0.035/0.036 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
@2011-07-20 02:11:15
CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 1.083/5.063 secs] [Times: user=1.08 sys=0.00, real=5.06 secs]
[GC[YG occupancy: 282204 K (2831168 K)][Rescan (parallel) , 0.0402030 secs][weak refs processing, 0.0010550 secs]
[1 CMS-remark: 4019122K(7340032K)] 4301 326K(10171200K), 0.0413630 secs] [Times: user=0.07 sys=0.01, real=0.04 secs]
@2011-07-20 02:11:16
[CMS-concurrent-sweep: 2.627/2.627 secs] [Times: user=2.63 sys=0.00, real=2.63 secs]
[CMS-concurrent-reset: 0.039/0.039 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
@2011-07-20 02:11:20
[GC [1 CMS-initial-mark: 4019034K(7340032K)] 4301238K(10171200K), 0.0308450 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
@2011-07-20 02:11:30
[CMS-concurrent-mark: 10.304/10.307 secs] [Times: user=20.48 sys=0.11, real=10.31 secs]
[CMS-concurrent-preclean: 0.018/0.019 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
@2011-07-20 02:11:35
CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 1.043/5.048 secs] Times: user=1.03 sys=0.00, real=5.05 secs]
[GC[YG occupancy: 282204 K (2831168 K)][Rescan (parallel) , 0.0419560 secs][weak refs processing, 0.0010880 secs]
[1 CMS-remark: 4019034K(7340032K)] 4301 238K(10171200K), 0.0431480 secs] [Times: user=0.07 sys=0.01, real=0.05 secs]
@2011-07-20 02:11:38
[CMS-concurrent-sweep: 2.622/2.622 secs] [Times: user=2.63 sys=0.00, real=2.62 secs]
[CMS-concurrent-reset: 0.039/0.039 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]

Answer 1

Try to play with UseCMSInitiatingOccupancyOnly & CMSInitiatingOccupancyFraction flags. Using these flags initiating the CMS collection will be triggered based on the occupancy. Also, probably there is sense to increase the size of tenured generation.