Need help with incremental GC failure

[Kevin McMurtrie]

I'm having a problem with the Java 1.4.2 incremental garbage collector
after the JVM has been running for about 15 hours. This is a Weblogic
server (J2SE features only) on Solaris/SPARC with 1GB of RAM. At first
the heaps seem to be aging nicely and incremental collection is smooth.
At some point, the GC train collapses and there are only mark and sweep
collections. The server stutters along with MSC until restarted.


JVM options:

-verbose:gc
-Xincgc
-ms150m -mx600m
-XX:NewSize=64m
-XX:MaxPermSize=256m
-XXermSize=128m
-XX:SurvivorRatio=4
-XX:+PrintTenuringDistribution
-XX:+JavaMonitorsInStackTrace
-XX:+PrintGCDetails

PermSize is being forced to 128MB because there were earlier problems
with it jamming at 55MB. It would then MSC on the "Perm" heap so
frequently that the JVM was non-functional.


This is what the GC logging looks like for the first 9 to 15 hours. It
does a MSC every several hours but it remains stable. The total memory
consumed after a MSC is stable so there are no significant leaks.

[06-18-2004 01:45:16] 3912.721: [GC
3912.727: [DefNew: 44718K->1807K(54656K), 0.1666485 secs]
3912.894: [Train: 30321K->30319K(88064K), 0.1170353 secs]
75040K->32126K(142720K), 0.2899359 secs]

[06-18-2004 01:45:47] 3943.916: [GC
3943.922: [DefNew: 45578K->1974K(54656K), 0.1908675 secs]
3944.113: [Train: 30319K->30319K(88064K), 0.1337683 secs]
75897K->54182K(142720K), 0.3308733 secs]

[06-18-2004 01:46:05] 3961.577: [GC
3961.584: [DefNew: 45750K->1971K(54656K), 0.1829183 secs]
3961.767: [Train: 30319K->30284K(88064K), 0.2217277 secs]
76070K->61440K(142720K), 0.4117500 secs]


Eventually, the New Heap jams and it does only MSC:


[06-18-2004 21:50:13] 76204.498: [GC
76204.596: [DefNew: 54655K->54655K(54656K), 0.0007877 secs]
76204.597: [Train MSC: 70250K->69545K(450880K), 6.0755309 secs]
124906K->80668K(505536K), 6.1755269 secs]

[06-18-2004 21:52:03] 76317.824: [GC
76318.769: [DefNew: 43775K->10880K(54656K), 1.2861563 secs]
76320.056: [Train: 70113K->70113K(450880K), 0.3464931 secs]
113321K->80993K(505536K), 2.5787924 secs]

[06-18-2004 21:53:45] 76417.927: [GC
76418.045: [DefNew: 54655K->54655K(54656K), 0.0008025 secs]
76418.046: [Train MSC: 70113K->69213K(450880K), 4.0647527 secs]
124768K->84925K(505536K), 4.1850703 secs]



The Tenuring log initially looks good:


Desired survivor size 5570560 bytes, new threshold 31 (max 31)
- age 1: 267416 bytes, 267416 total
- age 2: 238512 bytes, 505928 total
- age 3: 54000 bytes, 559928 total
- age 4: 349944 bytes, 909872 total
- age 5: 63856 bytes, 973728 total
- age 6: 48 bytes, 973776 total
- age 7: 224664 bytes, 1198440 total
- age 8: 141328 bytes, 1339768 total
- age 9: 89248 bytes, 1429016 total
- age 10: 68144 bytes, 1497160 total
- age 11: 51672 bytes, 1548832 total
- age 12: 47296 bytes, 1596128 total
- age 13: 84408 bytes, 1680536 total
- age 14: 38032 bytes, 1718568 total
- age 15: 5200 bytes, 1723768 total
- age 16: 69592 bytes, 1793360 total
- age 17: 45616 bytes, 1838976 total
- age 18: 12816 bytes, 1851792 total
- age 19: 10040 bytes, 1861832 total
- age 20: 10800 bytes, 1872632 total
- age 21: 29376 bytes, 1902008 total
- age 22: 3776 bytes, 1905784 total
- age 23: 24 bytes, 1905808 total
- age 24: 58288 bytes, 1964096 total
- age 25: 13448 bytes, 1977544 total
- age 26: 77088 bytes, 2054632 total

Desired survivor size 5570560 bytes, new threshold 31 (max 31)
- age 1: 274512 bytes, 274512 total
- age 2: 191528 bytes, 466040 total
- age 3: 236856 bytes, 702896 total
- age 4: 9712 bytes, 712608 total
- age 5: 339904 bytes, 1052512 total
- age 6: 63528 bytes, 1116040 total
- age 7: 48 bytes, 1116088 total
- age 8: 102896 bytes, 1218984 total
- age 9: 120184 bytes, 1339168 total
- age 10: 20424 bytes, 1359592 total
- age 11: 68144 bytes, 1427736 total
- age 12: 51672 bytes, 1479408 total
- age 13: 43176 bytes, 1522584 total
- age 14: 82784 bytes, 1605368 total
- age 15: 36800 bytes, 1642168 total
- age 16: 5200 bytes, 1647368 total
- age 17: 65472 bytes, 1712840 total
- age 18: 38928 bytes, 1751768 total
- age 19: 12744 bytes, 1764512 total
- age 20: 10040 bytes, 1774552 total
- age 21: 10800 bytes, 1785352 total
- age 22: 29376 bytes, 1814728 total
- age 23: 3776 bytes, 1818504 total
- age 24: 24 bytes, 1818528 total
- age 25: 58288 bytes, 1876816 total
- age 26: 13448 bytes, 1890264 total
- age 27: 77088 bytes, 1967352 total



At some point there will be a massive unloading of classes and the heap
train collapses. Notice that sections 14, 15, 19, 22, and 26 are
missing! From that point on, there is only one heap.

... lots of classes unloading ...

Desired survivor size 5570560 bytes, new threshold 31 (max 31)
- age 1: 5428920 bytes, 5428920 total
- age 2: 984 bytes, 5429904 total
- age 3: 568 bytes, 5430472 total
- age 4: 1128 bytes, 5431600 total
- age 5: 2336 bytes, 5433936 total
- age 6: 1664 bytes, 5435600 total
- age 7: 1152 bytes, 5436752 total
- age 8: 48 bytes, 5436800 total
- age 9: 344 bytes, 5437144 total
- age 10: 24 bytes, 5437168 total
- age 11: 2544 bytes, 5439712 total
- age 12: 2184 bytes, 5441896 total
- age 15: 3880 bytes, 5445776 total
- age 16: 3192 bytes, 5448968 total
- age 17: 400 bytes, 5449368 total
- age 19: 344 bytes, 5449712 total
- age 20: 392 bytes, 5450104 total
- age 21: 344 bytes, 5450448 total
- age 22: 24 bytes, 5450472 total
- age 23: 24 bytes, 5450496 total
- age 24: 24 bytes, 5450520 total
- age 26: 368 bytes, 5450888 total


Desired survivor size 5570560 bytes, new threshold 1 (max 31)
- age 1: 6542920 bytes, 6542920 total
- age 2: 3416 bytes, 6546336 total
- age 3: 872 bytes, 6547208 total
- age 4: 368 bytes, 6547576 total
- age 5: 1128 bytes, 6548704 total
- age 6: 2136 bytes, 6550840 total
- age 7: 1400 bytes, 6552240 total
- age 8: 808 bytes, 6553048 total
- age 9: 24 bytes, 6553072 total
- age 10: 344 bytes, 6553416 total
- age 11: 24 bytes, 6553440 total
- age 12: 2504 bytes, 6555944 total
- age 13: 2184 bytes, 6558128 total
- age 16: 3168 bytes, 6561296 total
- age 17: 1080 bytes, 6562376 total
- age 18: 48 bytes, 6562424 total
- age 20: 344 bytes, 6562768 total
- age 21: 24 bytes, 6562792 total
- age 23: 24 bytes, 6562816 total
- age 24: 24 bytes, 6562840 total
- age 25: 24 bytes, 6562864 total
- age 27: 368 bytes, 6563232 total

Desired survivor size 5570560 bytes, new threshold 1 (max 31)
- age 1: 11141120 bytes, 11141120 total

Desired survivor size 5570560 bytes, new threshold 1 (max 31)
- age 1: 11141120 bytes, 11141120 total

Desired survivor size 5570560 bytes, new threshold 1 (max 31)
- age 1: 11141120 bytes, 11141120 total

Desired survivor size 5570560 bytes, new threshold 1 (max 31)
- age 1: 11141120 bytes, 11141120 total


Any ideas on what could be causing this? I've used profiling to
optimize temporary object hotspots but that only delayed the failure for
a few more hours.

Thanks
- Kevin