Alarm is buzzing, heap is shrinking - Damn, it’s bug in JDK 1.5

Recently operation staff in an enterprise environment, reported that monitoring was generating "Low Free Memory" alerts for couple of applications. Interestingly, both impacted applications were recently migrated to WebLoic 9.2/JDK1.5.0 from WebLogic 8.1/JDK 1.4.2. Application monitoring had configured proactive alert on 5% free heap memory. There was no performance degradation was reported. No such alerts were generated when applications were on WebLogic 8.1/Java 1.4.2

Started troubleshooting with looking at heap configuration first.

-server -Xms1024m -Xmx1024m -XX:PermSize=128m -XX:MaxPermSize=128m -verbose:gc -XX:+PrintGCDetails -verbosegc -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -Xloggc:gc_log.log

Confirmed that initial and maximum heap are equal. Pulled out GC logs to dig inside JVM’s memory management.

GC logs was filled with numerous minor collections and only couple of Full collections. However I was bit surprised by looking at following lines in GC logs.

-------------------------------------------------
{Heap before gc invocations=1
……..
35.806: [GC [PSYoungGen: 262208K->21866K(305856K)] 262208K->21866K(1004928K), 0.1229916 secs]
.......
………..
{Heap before gc invocations=978
63680.214: [GC [PSYoungGen: 43674K->2284K(44992K)] 265851K->224801K(744064K), 0.0118684 secs]
--------------------------------------------------------

It indicated that heap had shrunken significantly even though Xms=-Xmx.

In first GC log(at start of the JVM), As expected it allocated 1G(305M “new generation” space + 699M “old generation” space) total heap.

At the last GC log heap had shrunken to 744M ( 699M “old generation” space + ~44M “new generation space). Actually “new generation” space had shrunken.

It prompted me to looks minor collection log right before FULL GC.

56100.763: [GC [PSYoungGen: 50837K->1088K(50944K)] 748089K->699874K(750016K), 0.0186458 secs]

Minor collection logs reported that free heap was ~2M.

With above observations, I concluded following

1) “new generation” space and heap size was shrinking. It is unexpected behavior from JVM’s part considering –Xms=Xmx configuration.
2) Shrinking “new generation” caused enormous minor collections.
3) It also generated false alarms even though plenty of actual available memory for allocation.


It didn’t take much time to locate known bug with JDK 1.5.0 with documented work around.
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6524727


Implemented work around by specifying “new generation” size explicitly.

-server -Xms1024m -Xmx1024m -Xmn335m -XX:PermSize=128m -XX:MaxPermSize=128m -verbose:gc -XX:+PrintGCDetails -verbosegc -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -Xloggc:gc_log.log


As expected above tuning, also reduced number minor collection in addition of fixing heap allocation at 1G.