We have a simple app that reads log files (1 at a time), and inserts the records into a DB.  Yesterday we observed two OOME's which coincide with Full GC's.  These Full GC's appear to be "premature" - meaning that the heap occupancy was well below the heap size when GC was triggered.  My best guess is that the Full GCs / OOME were caused by an extremely large allocation (e.g., > 1GB).  Is there any other reasonable explanation for this behavior?<br>
<br>Thanks,<br>Shane<br><br><br>2011-05-15T01:04:08.942-0400: 744918.391: [GC 744918.391: [DefNew: 32914K->365K(36288K), 0.0020476 secs] 443409K->410860K(520256K), 0.0020886 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>
2011-05-15T01:04:09.144-0400: 744918.593: [GC 744918.593: [DefNew: 32621K->323K(36288K), 0.0024427 secs] 443116K->410842K(520256K), 0.0024860 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>2011-05-15T01:05:08.487-0400: 744977.947: [GC 744977.954: [DefNew: 32579K->244K(36288K), 0.0028439 secs] 443098K->410763K(520256K), 0.0029446 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] <br>
2011-05-15T01:05:08.723-0400: 744978.182: [GC 744978.182: [DefNew: 32500K->636K(36288K), 0.0023190 secs] 443019K->411154K(520256K), 0.0023617 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>2011-05-15T01:05:08.906-0400: 744978.365: [GC 744978.366: [DefNew: 32892K->321K(36288K), 0.0021073 secs] 443410K->410842K(520256K), 0.0021459 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>
2011-05-15T01:05:13.378-0400: 744982.839: [GC 744982.839: [DefNew: 32577K->37K(36288K), 0.0016258 secs] 443098K->410558K(520256K), 0.0016636 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>2011-05-15T01:06:06.624-0400: 745036.095: [GC 745036.097: [DefNew: 10190K->48K(36288K), 0.0026042 secs]745036.100: [Tenured: 410520K->82745K(483968K), 0.5341348 secs] 420710K->82745K(520256K), [Perm : 9007K->9007K(12288K)], 0.5369732 secs] [Times: user=0.23 sys=0.00, real=0.54 secs] <br>
2011-05-15T01:06:07.166-0400: 745036.636: [Full GC 745036.636: [Tenured: 82745K->59599K(967936K), 0.4755627 secs] 82745K->59599K(1004288K), [Perm : 9007K->8935K(12288K)], 0.4758317 secs] [Times: user=0.15 sys=0.00, real=0.48 secs] <br>
2011-05-15T01:06:17.461-0400: 745046.933: [GC 745046.944: [DefNew: 64512K->488K(72576K), 0.0045634 secs] 124111K->60087K(1040512K), 0.0046410 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] <br>2011-05-15T01:07:08.690-0400: 745098.171: [GC 745098.181: [DefNew: 65000K->797K(72576K), 0.0041858 secs] 124599K->60397K(1040512K), 0.0042621 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] <br>
2011-05-15T01:07:09.694-0400: 745099.176: [GC 745099.176: [DefNew: 65309K->485K(72576K), 0.0016391 secs] 124909K->60085K(1040512K), 0.0016827 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>2011-05-15T01:08:08.858-0400: 745158.350: [GC 745158.357: [DefNew: 64997K->799K(72576K), 0.0036000 secs] 124597K->60399K(1040512K), 0.0036762 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] <br>
2011-05-15T01:08:11.512-0400: 745161.005: [GC 745161.005: [DefNew: 65311K->488K(72576K), 0.0015378 secs] 124911K->60088K(1040512K), 0.0015790 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>2011-05-15T01:08:34.926-0400: 745184.423: [GC 745184.433: [DefNew: 19958K->190K(72576K), 0.0020757 secs]745184.435: [Tenured: 59599K->59785K(967936K), 0.2253939 secs] 79558K->59785K(1040512K), [Perm : 9173K->9173K(12288K)], 0.2279033 secs] [Times: user=0.15 sys=0.00, real=0.24 secs] <br>
2011-05-15T01:08:35.164-0400: 745184.661: [Full GC 745184.661: [Tenured: 59785K->58941K(967936K), 0.3941210 secs] 59785K->58941K(1037056K), [Perm : 9173K->9165K(12288K)], 0.3947753 secs] [Times: user=0.15 sys=0.00, real=0.39 secs] <br>
2011-05-15T01:09:08.897-0400: 745218.400: [GC 745218.412: [DefNew: 51712K->346K(58176K), 0.0012630 secs] 110653K->59287K(832528K), 0.0013170 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] <br>2011-05-15T01:09:10.210-0400: 745219.714: [GC 745219.714: [DefNew: 52058K->330K(58176K), 0.0018250 secs] 110999K->59271K(832528K), 0.0018960 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>
2011-05-15T01:10:09.557-0400: 745279.072: [GC 745279.075: [DefNew: 52042K->653K(58176K), 0.0032786 secs] 110983K->59595K(832528K), 0.0429740 secs] [Times: user=0.00 sys=0.00, real=0.05 secs] <br>2011-05-15T01:10:11.557-0400: 745281.072: [GC 745281.072: [DefNew: 52365K->342K(58176K), 0.0010212 secs] 111307K->59284K(832528K), 0.0010563 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>
2011-05-15T01:11:08.779-0400: 745338.304: [GC 745338.316: [DefNew: 52054K->655K(58176K), 0.0028664 secs] 110996K->59596K(832528K), 0.0029585 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] <br>2011-05-15T01:11:10.138-0400: 745339.664: [GC 745339.664: [DefNew: 52367K->342K(58176K), 0.0010634 secs] 111308K->59284K(832528K), 0.0011042 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] <br>
2011-05-15T01:12:08.585-0400: 745398.121: [GC 745398.130: [DefNew: 52054K->752K(58176K), 0.0018517 secs] 110996K->59693K(832528K), 0.0019152 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] <br><br><br>2011-05-15 01:06:07,738  [Reader#0  ] ERROR ntroller.ReadLogFileWorker  - Exception processing file.<br>
java.lang.OutOfMemoryError: Java heap space<br>        at com.cpex.icelog.core.tradingengine.reader.SocketMessageLogReader.getNextSocketMessageByteStream(SocketMessageLogReader.java:159)<br>        at com.cpex.icelog.core.tradingengine.reader.SocketMessageLogReader.readLogEntries(SocketMessageLogReader.java:94)<br>
        at com.cpex.icelog.core.tradingengine.reader.SocketMessageLogReader.read(SocketMessageLogReader.java:287)<br>        at com.cpex.icelog.core.controller.ReadLogFileWorker.dispatchReader(ReadLogFileWorker.java:110)<br>
        at com.cpex.icelog.core.controller.ReadLogFileWorker.delegateDoRun(ReadLogFileWorker.java:81)<br>        at com.cpex.icelog.core.controller.ReadLogFileWorker.doRun(ReadLogFileWorker.java:63)<br>        at com.cpex.icelog.core.domain.IceLogProcessingRunnable.run(IceLogProcessingRunnable.java:37)<br>
        at edu.emory.mathcs.backport.java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:442)<br>        at edu.emory.mathcs.backport.java.util.concurrent.FutureTask.run(FutureTask.java:176)<br>        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)<br>
        at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)<br>        at java.lang.Thread.run(Thread.java:619)<br><br>