java GC periodically enters into several full GC cycles
- by Peter
Environment:
sun JDK 1.6.0_16
vm settings:
-XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -Xms1024 -Xmx1024M -XX:MaxNewSize=448m -XX:NewSize=448m -XX:SurvivorRatio=4(6 also checked) -XX:MaxPermSize=128M
OS: windows server 2003
processor: 4 cores of INTEL XEON 5130, 2000 Hz
my application description:
high intensity of concurrent(java 5 concurrency used) operations completed each time by commit to oracle.
it's about 20-30 threads run non stop, doing tasks.
application runs in JBOSS web container.
My GC starts work normally, I see a lot of small GCs and all that time CPU shows good load, like all 4 cores loaded to 40-50%, CPU graph is stable.
Then , after 1 min of good work, CPU starts drop to 0% on 2 cores from 4, it's graph becomes unstable, goes up and down("teeth"). I see, that my threads work slower(I have monitoring), I see that GC starts produce a lot of FULL GC during that time and next 4-5 minutes this situation remains as is, then for short period of time, like 1 minute, it gets back to normal situation, but shortly after that all bad thing repeats.
Question:
Why I have so frequent full GC???
How to prevent that?
I played with SurvivorRatio - does not help.
I noticed, that application behaves normally until first FULL GC occurs, while I have enough memory. Then it runs badly.
my GC LOG:
starts good
then long period of FULL GCs(many of them)
1027.861: [GC 942200K-623526K(991232K), 0.0887588 secs]
1029.333: [GC 803279K(991232K), 0.0927470 secs]
1030.551: [GC 967485K-625549K(991232K), 0.0823024 secs]
1030.634: [GC 625957K(991232K), 0.0763656 secs]
1033.126: [GC 969613K-632963K(991232K), 0.0850611 secs]
1033.281: [GC 649899K(991232K), 0.0378358 secs]
1035.910: [GC 813948K(991232K), 0.3540375 secs]
1037.994: [GC 967729K-637198K(991232K), 0.0826042 secs]
1038.435: [GC 710309K(991232K), 0.1370703 secs]
1039.665: [GC 980494K-972462K(991232K), 0.6398589 secs]
1040.306: [Full GC 972462K-619643K(991232K), 3.7780597 secs]
1044.093: [GC 620103K(991232K), 0.0695221 secs]
1047.870: [Full GC 991231K-626514K(991232K), 3.8732457 secs]
1053.739: [GC 942140K(991232K), 0.5410483 secs]
1056.343: [Full GC 991232K-634157K(991232K), 3.9071443 secs]
1061.257: [GC 786274K(991232K), 0.3106603 secs]
1065.229: [Full GC 991232K-641617K(991232K), 3.9565638 secs]
1071.192: [GC 945999K(991232K), 0.5401515 secs]
1073.793: [Full GC 991231K-648045K(991232K), 3.9627814 secs]
1079.754: [GC 936641K(991232K), 0.5321197 secs]
