Java garbage collection and young generation size

Question

I have recently been having performance difficulties where my Java webapp running on tomcat will hang for short periods resulting in backlogs of traffic which can make the webapp unavailable for minutes at a time which I suspect is related to garbage collection.

I am a garbage collection noob so need a bit of help.

I have enabled the Concurrent Mark Sweep garbage collector in the hope this will eliminate the pauses however I am yet to discover if this has resolved the problem yet.

I also enabled verbose GC logging at the same time.

Current java options are as follows

-XX:MaxPermSize=128m -XX:+CMSClassUnloadingEnabled -XX:+UseConcMarkSweepGC -Xms4g -Xmx4g -Xss256k -verbose:gc -XX:+PrintGCDetails

I have noticed from examining the GC output that the the young generation space is quite low at 243MB and is getting exhausted quickly, while examining the output for a period of time I was counting 23 young generation collections in 10 seconds.

At the same time the total heap consumption is steadily rising reaching near the maximum followed by a full garbage collection which is taking it down from about 3.5gb to 260mb and then the pattern repeats its self again.

Sample output with a full GC

[GC [ParNew: 232750K->12960K(249216K), 0.0160890 secs] 3836696K->3616934K(4166656K), 0.0162110 secs] [Times: user=0.12 sys=0.01, real=0.02 secs] 
[GC [ParNew: 234528K->11391K(249216K), 0.0127970 secs] 3838502K->3615402K(4166656K), 0.0129370 secs] [Times: user=0.12 sys=0.00, real=0.01 secs] 
[GC [ParNew: 232959K->10253K(249216K), 0.0097850 secs] 3836970K->3614841K(4166656K), 0.0098850 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
[GC [1 CMS-initial-mark: 3604588K(3917440K)] 3615964K(4166656K), 0.0096810 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[CMS-concurrent-mark: 0.196/0.196 secs] [Times: user=1.44 sys=0.03, real=0.20 secs] 
[CMS-concurrent-preclean: 0.013/0.014 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
[GC [ParNew: 231821K->6718K(249216K), 0.0090430 secs] 3836409K->3611789K(4166656K), 0.0091460 secs] [Times: user=0.08 sys=0.01, real=0.01 secs] 
[CMS-concurrent-abortable-preclean: 0.176/0.390 secs] [Times: user=0.97 sys=0.04, real=0.39 secs] 
[GC[YG occupancy: 124723 K (249216 K)][Rescan (parallel) , 0.0698120 secs][weak refs processing, 0.0038070 secs][class unloading, 0.0170180 secs][scrub symbol & string tables, 0.0098050 secs] [1 CMS-remark: 3605071K(3917440K)] 3729794K(4166656K), 0.1070920 secs] [Times: user=0.78 sys=0.02, real=0.11 secs] 
[GC [ParNew: 228286K->6428K(249216K), 0.0079910 secs] 3755282K->3534155K(4166656K), 0.0080720 secs] [Times: user=0.07 sys=0.00, real=0.01 secs] 
[GC [ParNew: 227996K->6880K(249216K), 0.0085010 secs] 3332282K->3111216K(4166656K), 0.0085990 secs] [Times: user=0.08 sys=0.00, real=0.01 secs] 
[GC [ParNew: 228448K->12440K(249216K), 0.0108230 secs] 2721177K->2505200K(4166656K), 0.0109290 secs] [Times: user=0.13 sys=0.00, real=0.01 secs] 
[GC [ParNew: 234008K->8251K(249216K), 0.0073110 secs] 2358432K->2132792K(4166656K), 0.0074120 secs] [Times: user=0.07 sys=0.00, real=0.00 secs] 
[GC [ParNew: 229819K->5170K(249216K), 0.0071920 secs] 2056138K->1831867K(4166656K), 0.0072880 secs] [Times: user=0.07 sys=0.01, real=0.01 secs] 
[GC [ParNew: 226738K->11119K(249216K), 0.0106230 secs] 1589903K->1374447K(4166656K), 0.0107180 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
[GC [ParNew: 232687K->8624K(249216K), 0.0078450 secs] 1273082K->1049051K(4166656K), 0.0079440 secs] [Times: user=0.09 sys=0.00, real=0.01 secs] 
[GC [ParNew: 230192K->10130K(249216K), 0.0083440 secs] 733461K->513411K(4166656K), 0.0084420 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
[GC [ParNew: 231698K->10655K(249216K), 0.0092440 secs] 544833K->323816K(4166656K), 0.0093450 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
[CMS-concurrent-sweep: 4.481/4.569 secs] [Times: user=13.24 sys=0.49, real=4.57 secs] 
[CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[GC [ParNew: 232223K->9791K(249216K), 0.0095050 secs] 495665K->273758K(4166656K), 0.0096020 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] 
[GC [ParNew: 231359K->7434K(249216K), 0.0080890 secs] 495326K->271660K(4166656K), 0.0082230 secs] [Times: user=0.09 sys=0.00, real=0.01 secs] 
[GC [ParNew: 229002K->5732K(249216K), 0.0053690 secs] 493228K->269993K(4166656K), 0.0054630 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
[GC [ParNew: 227300K->4017K(249216K), 0.0060080 secs] 491561K->268433K(4166656K), 0.0061010 secs] [Times: user=0.07 sys=0.00, real=0.00 secs] 

I would like to understand if this pattern seems normal and what I can do to optimise and improve thisC.

I have read about increasing the young generation size but not being too familiar with garbage collection i'm not sure if this is the right approach.

Answer 1

This does look like your young generation size is too small - frequent collections aren't really the issue (this just means that you have a memory-intensive program), but it's problematic that you have a lot of memory being promoted to the next generation. A few things:

1. Do you have any resources that you can pool, e.g. can you use a ThreadPoolExecutor instead of creating new Thread objects, or can you pool your database connections? This will slow down your memory consumption - the pooled resources will stay in your mature space and you won't have to keep reallocating them in your young space.

2. If that's not an option or if that doesn't reduce your mature space consumption, then increase your young generation size. The purpose of this isn't to reduce the number of young generation collections (if you double the young generation size then you will halve the number of collections but each collection may cost twice as much**, so you haven't gained anything), rather the purpose of this is to allow more time for your young objects to go out of scope so that they're not promoted to mature space. The comparison you want to make is the frequency of full collections - if you have fewer full collections after increasing your young generation size then you've succeeded, otherwise reduce your young generation size back to the default.

** This isn't strictly true, because the young generation collector is a copying collector - it copies live objects to the mature space, then clears the young space. This means that the collector runs in time proportional to the number of live objects, NOT in time proportional to the total number of objects (as is the case with a mark-sweep collection). Ideally, by increasing your young generation size you'll reduce the number of live objects and speed up collection times as well as reducing mature space consumption.