views:

1324

answers:

5

I have my java application configured to use 5G memory. I got an OutOfMemory out of blue. I inspected the gc log and found plenty of memory left: young generation occupies 4% allocated space, tenure generation occupancy is 5% and perm generation is 43%. I am puzzled why JVM throws an OutOfMemory at the gc time. Does anyone know why this is happening? Your help is greatly appreciated.

JVM memory and gc settings:

-server -Xms5g -Xmx5g -Xss256k -XX:NewSize=2g -XX:MaxNewSize=2g -XX:+UseParallelOldGC -XX:+UseTLAB -XX:SurvivorRatio=8 -XX:TargetSurvivorRatio=90 -XX:+DisableExplicitGC

gc.log

2009-09-19T03:34:59.741+0000: 92836.778: [GC
Desired survivor size 152567808 bytes, new threshold 1 (max 15)
 [PSYoungGen: 1941492K->144057K(1947072K)] 3138022K->1340830K(5092800K), 0.1947640 secs] [Times: user=0.61 sys=0.01, real=0.19 secs] 
2009-09-19T03:35:29.918+0000: 92866.954: [GC
Desired survivor size 152109056 bytes, new threshold 1 (max 15)
 [PSYoungGen: 1941625K->144049K(1948608K)] 3138398K->1341080K(5094336K), 0.1942000 secs] [Times: user=0.61 sys=0.01, real=0.20 secs] 
2009-09-19T03:35:56.883+0000: 92893.920: [GC
Desired survivor size 156565504 bytes, new threshold 1 (max 15)
 [PSYoungGen: 1567994K->115427K(1915072K)] 2765026K->1312820K(5060800K), 0.1586320 secs] [Times: user=0.50 sys=0.01, real=0.16 secs] 
2009-09-19T03:35:57.042+0000: 92894.079: [GC
Desired survivor size 179961856 bytes, new threshold 1 (max 15)
 [PSYoungGen: 115427K->0K(1898560K)] 1312820K->1313987K(5044288K), 0.0775650 secs] [Times: user=0.42 sys=0.19, real=0.08 secs] 
2009-09-19T03:35:57.120+0000: 92894.157: [Full GC [PSYoungGen: 0K->0K(1898560K)] [ParOldGen: 1313987K->159522K(3145728K)] 1313987K->159522K(5044288K) [PSPermGen: 20025K->19942K(40256K)], 0.56923
00 secs] [Times: user=2.18 sys=0.05, real=0.57 secs] 
2009-09-19T03:35:57.690+0000: 92894.726: [GC
Desired survivor size 197066752 bytes, new threshold 1 (max 15)
 [PSYoungGen: 0K->0K(1745728K)] 159522K->159522K(4891456K), 0.0072590 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2009-09-19T03:35:57.698+0000: 92894.734: [Full GC [PSYoungGen: 0K->0K(1745728K)] [ParOldGen: 159522K->158627K(3145728K)] 159522K->158627K(4891456K) [PSPermGen: 19942K->19934K(45504K)], 0.3280480
 secs] [Times: user=1.46 sys=0.00, real=0.33 secs] 
Heap
 PSYoungGen      total 1745728K, used 87233K [0x00002aab73650000, 0x00002aabf3650000, 0x00002aabf3650000)
  eden space 1745664K, 4% used [0x00002aab73650000,0x00002aab78b80778,0x00002aabddf10000)
  from space 64K, 0% used [0x00002aabddf10000,0x00002aabddf10000,0x00002aabddf20000)
  to   space 192448K, 0% used [0x00002aabe7a60000,0x00002aabe7a60000,0x00002aabf3650000)
 ParOldGen       total 3145728K, used 158627K [0x00002aaab3650000, 0x00002aab73650000, 0x00002aab73650000)
  object space 3145728K, 5% used [0x00002aaab3650000,0x00002aaabd138d28,0x00002aab73650000)
 PSPermGen       total 45504K, used 19965K [0x00002aaaae250000, 0x00002aaab0ec0000, 0x00002aaab3650000)
  object space 45504K, 43% used [0x00002aaaae250000,0x00002aaaaf5cf668,0x00002aaab0ec0000)


I am on 64-bit Linux and JRE 1.6.0_10:

$uname -a
Linux x 2.6.24-etchnhalf.1-amd64 #1 SMP Tue Oct 14 03:11:45 UTC 2008 x86_64 GNU/Linux 

$java -version
java version "1.6.0_10" 
Java(TM) SE Runtime Environment (build 1.6.0_10-b33) 
Java HotSpot(TM) 64-Bit Server VM (build 11.0-b15, mixed mode)
A: 

I don't see a setting for "-XX:MaxPermSize". Why not? I'd add one.

What are you using to watch memory? I'd recommend jvmstat.

duffymo
if the issue was related to perm size he would get a PermGen error
Taylor Leese
Please point out the PermGenError in java.lang. I don't see one. I've seen out of memory errors triggered by the perm space filling up with .class files, usually in conjunction with something like JAXB that auto generates a lot of classes.
duffymo
The OutOfMemoryError message would then include a hint that is was lacking PermGen. This is done since Java 5 IIRC. That's why you normally see a reference to the heap - as there the OOMEs are most common.
Daniel Schneller
A: 

Also, what's the detail with the OutOfMemoryException - is it to do with the GC overhead limit? If so, that exception can be disabled (-XX:-UseGCOverheadLimit)

See this page about gc options and their explanation

daveb
I've tried this. It didn't work. I guess the root cause is something else.
Shu L.
A: 

We're seeing the exact same problem (gee, wonder how we got to this thread? :) We see repeated instances of:

  • An incremental GC yielding a YounGen usage stat of 0K->0k
  • A FULL GC seeing the same thing (0K->0K)
  • Attempt to allocate memory right about that time
  • A bogus Java heap out of memory crash

Notes:

  1. We are using the default GC
  2. We set MaxPermSize to 256M
  3. While PermGen is shown to be 99% full, its high water mark is nowhere near 256M: thus, we believe this to be a red herring.

Here are some log messages:

Sep 11 05:37:07 7 09646: Server: [Full GC [PSYoungGen: 320K->0K(146688K)] [PSOldGen: 1302885K->1303138K(1365376K)] 1303205K->1303138K(1512064K) [PSPermGen: 81386K->81386K(81792K)], 5.4624360 secs] [Times: user=4.89 sys=0.58, real=5.46 secs]
Sep 11 05:37:07 7 09646: Server: [GC [PSYoungGen: 0K->0K(122624K)] 1303138K->1303138K(1488000K), 0.0124180 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
Sep 11 05:37:13 7 09646: Server: [Full GC [PSYoungGen: 0K->0K(122624K)] [PSOldGen: 1303138K->1302947K(1365376K)] 1303138K->1302947K(1488000K) [PSPermGen: 81386K->81378K(81792K)], 5.9120130 secs] [Times: user=5.65 sys=0.25, real=5.91 secs]
Sep 11 05:37:13 7 09646: Server: java.lang.OutOfMemoryError: Java heap space
Sep 11 05:37:13 7 09646: Server: \09at java.util.HashMap.resize(HashMap.java:462)
Sep 11 05:37:13 7 09646: Server: \09at java.util.HashMap.addEntry(HashMap.java:755)
Sep 11 05:37:13 7 09646: Server: \09at java.util.HashMap.put(HashMap.java:385)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.core.ds.MapThreadWrapper.put(MapThreadWrapper.java:175)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.Application.addResource(Application.java:514)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.Resource.<init>(Resource.java:68)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.Resource.<init>(Resource.java:60)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.Resource$AnimResource.<init>(Resource.java:529)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.HmeObject.createAnimation(HmeObject.java:559)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.Application.createResource(Application.java:626)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.Application.getResource(Application.java:559)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.sdk.HmeObject.getResource(HmeObject.java:221)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.rhapsody.widgets.SimilarAlbum.moveLeft(SimilarAlbum.java:162)
Sep 11 05:37:13 7 09646: Server: \09at com.tivo.hme.rhapsody.screens.MediaPlayerScreen$WaitingThread.run(MediaPlayerScreen.java:437)
Sep 11 05:37:13 7 09646: Server: Exiting due to java.lang.OutOfMemoryError
Sep 11 05:37:13 7 09646: Server: Exiting due to java.lang.OutOfMemoryError
Sep 11 05:37:13 7 09646: Server: Heap
Sep 11 05:37:13 7 09646: Server:  PSYoungGen      total 122624K, used 6762K [0xaa7a0000, 0xb4d90000, 0xb4e40000)
Sep 11 05:37:13 7 09646: Server:   eden space 122560K, 5% used [0xaa7a0000,0xaae3a9c0,0xb1f50000)
Sep 11 05:37:13 7 09646: Server:   from space 64K, 0% used [0xb1f50000,0xb1f50000,0xb1f60000)
Sep 11 05:37:13 7 09646: Server:   to   space 23680K, 0% used [0xb3670000,0xb3670000,0xb4d90000)
Sep 11 05:37:13 7 09646: Server:  PSOldGen        total 1365376K, used 1302947K [0x57240000, 0xaa7a0000, 0xaa7a0000)
Sep 11 05:37:13 7 09646: Server:   object space 1365376K, 95% used [0x57240000,0xa6aa8d38,0xaa7a0000)
Sep 11 05:37:13 7 09646: Server:  PSPermGen       total 81792K, used 81408K [0x47240000, 0x4c220000, 0x57240000)
Sep 11 05:37:13 7 09646: Server:   object space 81792K, 99% used [0x47240000,0x4c1c02c0,0x4c220000)
Sep 11 05:37:14 5 09646: Server exited with "immediate restart" exit code (exit code = 2), restarting in 1 second(s)
It's very dangerous to assume that two exceptions have the same cause just because they're the same exception. However, unlike the OP, you gave a stack trace, which gives some hints.
kdgregory
You got the exception in HashMap.resize(), which will need to allocate a potentially large, *contiguous* block of memory for its hash table. Large arrays typically get allocated in the tenured space, and looking at the GC report, you're pretty close to maxed out in that space (95%). Check the size of your map, I'm betting it's several hundred thousand entries.
kdgregory
Incidentally, it looks like you're constantly running collections on the old generation, while the young generation seems to remain empty. I'd recommend doing an analysis of the objects in your program -- if you're creating lots of large arrays, it may make more sense to change your GC params.
kdgregory
How did you get JVM to dump the call stack for OOM? I don't even see the call stack in my gc.log. Is it printed to console?
Shu L.
is it -XX:+HeapDumpOnOutOfMemoryError?
Shu L.
A: 

Okay, probably a stupid answer but your box does have at least 5GB of RAM, right? Just checking. :-) I can't remember if the JVM actually checks whether or not you actually have enough memory until It actually tries to allocate it.

cjstehno
A: 

You might want to consider using a profiler and debugger to understand exact state in which out of memory error occurs.

I use Jprofiler for profiling and Eclipse's Debugger for debugging. Both have sufficient features for their purpose.

I would have also liked to see stack trace of error to identify kind of error and where exactly it starts coming. This is very important information missing from question.

YoK