GC long pauses with CMS
We are testing Telco application based on Java OSGI and in long runs experiencing pauses over 2-10 seconds. Since it is Telco area, reducing long pauses is very important.
Hardware is FSC Blade BX600 dual core Intel Xeon 3.0 Ghz ,Hyperthreading (4 logical CPUs - 2 year old hardware)
SLES 9 SP2 32 bit
2GB of RAM
JRE : Sun 1.5.0_12
We were forced to increase permanent space due to out of memory in the permanent space. In previous tests in trace logs I have identified often young collection (parallel new) with young space size of 16m, not keeping up, so we increased to 64m. However this is not our main problem. Main problem is further long full collections and often "concurrent mode failures" occasionally followed by class unloading.
Below are traces from the last session. I found lot of tweaking advices, but currently I am lost in a variety of options to tune.
Another observation is that our CMS concurrent phases last too long (CMS-concurrent-mark: 1.030/69.455 secs).
Here is couple of typical traces:
Application time: 47.1989000 seconds
1368.943: [Full GC 1368.943: [CMS1369.393: [CMS-concurrent-mark: 1.030/69.455 secs]
(concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor120]
[Unloading class sun.reflect.GeneratedMethodAccessor631]
[Unloading class sun.reflect.GeneratedMethodAccessor497]
: 118174K->98861K(458752K), 2.5512070 secs] 147043K->98861K(524224K), [CMS Perm : 116709K->115734K(194532K)] icms_dc=10 , 2.5518450 secs]
Total time for which application threads were stopped: 2.5544050 seconds
493.187: [Full GC 1493.187: [CMS1494.003: [CMS-concurrent-mark: 0.816/60.808 secs]
(concurrent mode failure)[Unloading class sun.reflect.GeneratedMethodAccessor945]
[Unloading class sun.reflect.GeneratedMethodAccessor950]
[Unloading class sun.reflect.GeneratedMethodAccessor941]
[Unloading class sun.reflect.GeneratedMethodAccessor940]
[Unloading class sun.reflect.GeneratedMethodAccessor948]
Mon Dec 17 17:26:35 CET 2007
: 92028K->92583K(458752K), 2.4635680 secs] 107507K->92583K(524224K), [CMS Perm : 115782K->115772K(194532K)] icms_dc=10 , 2.4641410 secs]
Total time for which application threads were stopped: 2.4665520 seconds
13424.288: [Full GC 13424.288: [CMS13424.288: [CMS-concurrent-abortable-preclean: 2.156/98.536 secs]
(concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor330]
[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor342]
...//around 180 classes unloaded
[Unloading class sun.reflect.GeneratedMethodAccessor2045]
: 386880K->369517K(458752K), 4.9890290 secs] 391575K->369517K(524224K), [CMS Perm : 116642K->116317K(194916K)] icms_dc=100 , 4.9895980 secs]
Total time for which application threads were stopped: 4.9920160 seconds