Cause of Full GCs / OOME

Y. Srinivas Ramakrishna y.s.ramakrishna at oracle.com
Mon May 16 15:41:17 UTC 2011 

On 5/16/2011 4:52 AM, Shane Cox wrote:
> 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?

I think you are right that this must be for an allocation that is too large to
fit in either or the two generations (old or young). Does that appear reasonable
for the kind of allocation that the OOME stack trace shows at:
com.cpex.icelog.core.tradingengine.reader.SocketMessageLogReader.getNextSocketMessageByteStream(SocketMessageLogReader.java:159)

Looking at the heap in the temporal vicinity of the OOME, we find:-

 > 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]
 > 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]

that following the second GC, there was 967936K - 59599K = 908337 K of free space
in the old generation, so it seems reasonable to me that this was an allocation
request whose size exceeded that value.

The two GC's indicate the JVM escalating the collection: it first attempts to
do a normal full gc to try and satisfy the allocation request. When the available
space still falls short, it follows up with a collection that clears any soft references
held by the VM, and retries the allocation. This also seems to fail. I'd try and
bound the size at the allocation site or, failing that, size the heap sufficiently
large to allow such large allocations from time to time.

-- ramki


>
> Thanks,
> Shane
>
>
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
> 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]
>
>
> 2011-05-15 01:06:07,738  [Reader#0  ] ERROR ntroller.ReadLogFileWorker  -
> Exception processing file.
> java.lang.OutOfMemoryError: Java heap space
>          at
> com.cpex.icelog.core.tradingengine.reader.SocketMessageLogReader.getNextSocketMessageByteStream(SocketMessageLogReader.java:159)
>          at
> com.cpex.icelog.core.tradingengine.reader.SocketMessageLogReader.readLogEntries(SocketMessageLogReader.java:94)
>          at
> com.cpex.icelog.core.tradingengine.reader.SocketMessageLogReader.read(SocketMessageLogReader.java:287)
>          at
> com.cpex.icelog.core.controller.ReadLogFileWorker.dispatchReader(ReadLogFileWorker.java:110)
>          at
> com.cpex.icelog.core.controller.ReadLogFileWorker.delegateDoRun(ReadLogFileWorker.java:81)
>          at
> com.cpex.icelog.core.controller.ReadLogFileWorker.doRun(ReadLogFileWorker.java:63)
>          at
> com.cpex.icelog.core.domain.IceLogProcessingRunnable.run(IceLogProcessingRunnable.java:37)
>          at
> edu.emory.mathcs.backport.java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:442)
>          at
> edu.emory.mathcs.backport.java.util.concurrent.FutureTask.run(FutureTask.java:176)
>          at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
>          at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
>          at java.lang.Thread.run(Thread.java:619)
>
>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

More information about the hotspot-gc-dev mailing list