Tuesday, June 15, 2010

Java Garbage Collection : Unexpected Full GC

I've been digging garbage collection logs these days. We have a production server which suffers long pauses of garbage collection. According to garbage collection log file, there are three different cases that force the JVM to do a StopTheWorld collection:

1. Full GC after a promotion failure: This is the evidence of not enough contiguous space in the old (tenured) generation. The simplest solution to this is increasing heap size. (I am glad it worked for us.)

2. Full GC after a concurrent mode failure (in other words; full promotion guarantee failure) : CMS collector can not catch up with the object allocation speed of the application. If this is the case try setting CMSInitiatingOccupancyFraction to a lower value. CMS will start early but will finish its job on-time.

3. The third one was very difficult for me to figure out. Here is what it looks like: Everything seems to work fine but suddenly Full GC kicks in and 37 seconds of break for application threads.

216066.711: [GC 216066.713: [ParNew: 911554K->71428K(943744K), 0.0860545 secs] 2346321K->1508264K(4089472K), 0.0878449 secs] [Times: user=3.63 sys=0.32, real=0.09 secs]
216066.896: [Full GC 216066.897: [CMS: 1436836K->1003062K(3145728K), 37.8691646 secs] 1527124K->1003062K(4089472K), [CMS Perm : 86016K->31249K(86016K)], 37.8707796 secs] [Times: u
ser=37.64 sys=0.35, real=37.87 secs]
216106.398: [GC 216106.399: [ParNew: 838912K->46337K(943744K), 0.0555625 secs] 1841974K->1049399K(4089472K), 0.0573404 secs] [Times: user=1.33 sys=0.45, real=0.06 secs]
The above log says that in order to clean permanent generation a full collection occured and (86016 - 31249) kilobytes of space freed in permanent generation.

What I've learned today is : The garbage of the permanent generation is only collected by a Full GC. If you see unexpected full collections try expanding permanent generation.

7 comments:

Anonym said...

There can also be full GCs for no apparent reason if you use a lot of, or large, nio Direct Buffers. Since it is very hard to get stats on those it´s very hard to diagnose.

Asif said...

a question from the journeyman...to the master. i read it somewhere that permgen means it is permanent and objects once put on this space will not be removed no matter what you try...and your log is saying that your permgen got Garbage collected(I have mainly worked with Sun VM , so at least in that one i am pretty sure that there are no documented switches which say that you can collect permgen space). please enlighten....
ASIF

İlkin Ulaş BALKANAY said...

Where did you read that?
If you like here's a blog post from a member of the garbage collection team in Sun(Oracle).
http://blogs.sun.com/jonthecollector/entry/presenting_the_permanent_generation

When the class definitions are garbage collected from the Perm. Gen. jvm outputs logs like these:

[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor268]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor363]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor126]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor98]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor79]

karussell said...

I think Asif means sth. like the link in the first comment of the accepted answer here: http://stackoverflow.com/questions/88235/how-to-deal-with-java-lang-outofmemoryerror-permgen-space-error

Kirk Gray said...

Encouraging people to expand Perm Space more and more is not really responsible. There are plenty of ways to approach this issue. I blogged about it a while back - http://kirkgsworld.blogspot.com/2009/03/garbage-collection-tomcat-hibernate-and.html

There are plenty of different ways to approach this, but proper sizing is just one of them.

Rich Taylor said...

Have a look at the CMSClassUnloadingEnabled JVM option. I've been doing some testing in our environment (Java 6) with it. My understanding is that it will clean up classes (presumably in PermGen) concurrently, just as the CMS cleans up the tenured space concurrently. With a combination of UseConcMarkSweepGC, UseParNewGC, CMSClassUnloadingEnabled it appears all generations are being cleaned up in a CMS style. I haven't seen a "Full GC" yet in our load testing. (Oh I also disabled explicit GCs with DisableExplicitGC, I'm leaving the decision of when to do its work up to the GC itself.

İlkin Ulaş BALKANAY said...

Thanks for your advice. We are also testing CMSClassUnloadingEnabled flag. As you said, cms is also cleaning up the perm gen.