Heap OOM for no apparent reason?

[Raman Gupta]

I am getting a heap OOM for no apparent reason. Normally permanent generation size or a large finalization queue would be culprits for this sort of OOM, but AFAICT GC logs and heap dump show that neither is the case here. There is also no native code being executed.

Linux RHEL 5.6

java version "1.6.0_24"
Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
Java HotSpot(TM) 64-Bit Server VM (build 19.1-b02, mixed mode)

(I have also tried it with 1.6.0_25 64-bit and 1.6.0_25 32-bit with the same OOM result for both, but the logs below are from 1.6.0_24 64-bit).

Startup parameters:

-server 
-Xms256m 
-Xmx256m 
-XX:+HeapDumpOnOutOfMemoryError
-XX:MaxPermSize=64m
-verbose:gc 
-XX:-UseGCOverheadLimit 
-XX:+DisableExplicitGC 
-XX:+UseParallelGC 
-XX:+UseFastAccessorMethods 
-XX:AdaptiveSizePolicyOutputInterval=1 
-XX:+PrintGCDateStamps 
-XX:+PrintGCTimeStamps 
-XX:+PrintGCDetails 
-XX:+PrintGCApplicationConcurrentTime 
-XX:+PrintGCApplicationStoppedTime

The complete GC log is available here:

http://dl.dropbox.com/u/3430279/gc.log

but here is a short snippet from that log before and after the OOM:

2011-05-27T11:35:18.214-0400: 147.823: [Full GC [PSYoungGen: 7662K->0K(72896K)] [PSOldGen: 169093K->62518K(174784K)] 176755K->62518K(247680K) [PSPermGen: 27342K->27342K(55232K)], 0.8074580 secs] [Times: user=0.29 sys=0.03, real=0.81 secs] 
2011-05-27T11:35:19.022-0400: 148.632: [Full GC [PSYoungGen: 0K->0K(57856K)] [PSOldGen: 62518K->52158K(174784K)] 62518K->52158K(232640K) [PSPermGen: 27342K->26866K(61056K)], 0.3614330 secs] [Times: user=0.32 sys=0.02, real=0.37 secs] 
Total time for which application threads were stopped: 1.2760680 seconds
java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid18706.hprof ...
Application time: 0.9442610 seconds
Total time for which application threads were stopped: 2.4584870 seconds
Heap dump file created [83874513 bytes in 3.330 secs]
2011-05-27T11:35:30.942-0400: 160.552: [Full GC [PSYoungGen: 2624K->0K(44800K)] [PSOldGen: 86916K->76124K(174784K)] 89540K->76124K(219584K) [PSPermGen: 26902K->26902K(58880K)], 0.2801510 secs] [Times: user=0.28 sys=0.00, real=0.28 secs] 

Note that:

1) I can reproduce this easily.

2) This seems to happen only once shortly after load is applied to the system shortly after startup -- after that everything seems fine (though I haven't yet verified this with a longer test).

3) There is *always* a Full GC showing a young generation 0K->0K collection before this happens.

4) There seems to be plenty of space in the tenured generation as well as in permanent at OOM time.

5) The heap dump in pid18706.hprof shows only 70 MB of live objects in the heap.

6) The heap dump in pid18706.hprof shows no objects in the finalization queue.

7) I note the OutOfMemoryError in the log does not have any stack trace associated with it as is normally present.

8) When running the JVM with hprof sites profiling turned on (-agentlib:hprof=heap=sites) no OOM occurs (though again I did not try a very long test).

I'm not sure what else to try or where else to look. Any suggestions?

Cheers,
Raman Gupta