7

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]

Dhana Krishnasamy
  • 2,126
  • 17
  • 36

2 Answers2

4

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.

Stas
  • 1,707
  • 15
  • 25
  • yes the CMS is was getting triggered when UseCMSInitiatingOccupancy reached 68% and the rate of message inflow was pusing it to 68% often.. that was the issue.. and u hit the spot – Dhana Krishnasamy Jul 24 '11 at 15:21
  • You could check this location for details: http://stackoverflow.com/questions/9697754/cms-garbage-collector-when-does-it-run – RRM Apr 04 '14 at 12:27
3

What about memory fragmentation? Concurrent mark-and-sweep doesn't compact memory and it can become very fragmented eventually - so though you have enough total space, you might not have enough space to allocate new object; and so GC is started.

Andrey Nudko
  • 41
  • 1