Cause of Full GCs / OOME

Shane Cox shane.cox at gmail.com
Mon May 16 04:52:08 PDT 2011


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?

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)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20110516/48872bea/attachment.html 
-------------- next part --------------
_______________________________________________
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