Unexpected Java 6 vs 8 GC performance difference
Hughes,Corbin
Corbin.Hughes at Cerner.com
Fri May 27 20:07:35 UTC 2016
Hello,
We're having some issues with large GC performance discrepancies between Java 6
and Java 7 or 8, and I'm hoping someone can help shed some light.
The application in question loads in about 1.5 GB of immutable caches,
then, while this sits in the OldGen, we have requests come in that generate
huge amounts of very short lived objects (~1 GB or so per request) that
fill up the eden space and then get cleaned up. It's very rare that anything
will last more than 1 GC cycle. Usually 2-10MB or so goes into the survivor
space, and then nothing makes it past survivor through enough GC cycles to
get into the OldGen.
This current setup in Java 6 is pretty much ideal for us: young gen collections
are very fast, and other than the initial cache loading, we never do full GC.
The problem is that we're seeing ~10 ms PSYoungGen collections in Java 6, but
~200 ms PSYoungGen collections in Java 7 and 8.
I thought for a while that it might have been due to extra garbage being
generated via the String.substring changes or something of that nature, but
according to the GC logs, over 1500 requests, Java 6 and Java 8 are
collecting equal amounts (or rather less than a fraction of a percent
different) of memory. Furthermore, the two different versions of Java are
even making very similar amounts of PSYoungGen collections: 759 for Java 6, 744
for Java 8.
Everything I can see seems to be the same: number of GCs, amount of garbage
collected, etc. The only difference is that the collections take longer in Java 7
and Java 8, and I'm struggling to figure out why.
Though other versions of Java exhibit the same behavior, we're using JDK 6u101
and JDK 8u92 with the following settings:
Java 6:
-Xms5g -Xmx5g -XX:NewSize=2g -XX:MaxNewSize=2g -XX:PermSize=800m \
-XX:MaxPermSize=1g -XX:StringTableSize=5834701
Java 8:
-Xms6g -Xmx6g -XX:NewSize=2g -XX:MaxNewSize=2g -XX:MaxPermSize=1g \
-Djava.util.Arrays.useLegacyMergeSort=true -XX:StringTableSize=5834701
Since interned strings no longer go in the PermGen, the OldGen size is
upped a bit in Java 8 to compensate. We have tested with the exact same
settings though since the OldGen can technically fit the interned strings,
and results are the same.
We've also tested various young gen sizes for Java 8, and oddly enough,
massively increasing the young gen practically makes no difference in
collection time. Whether the young gen is 1 GB, 2 GB or 16 GB, the collections
still take 200 ms. We've also noticed that the bottleneck appears to be on a
single thread since the real time and the user time are very nearly equal. This
implies to us that something serial is happening that is not proportional to
the size of the young gen but of something else, something that's staying
constant.
To analyze GC logs, we've been using GCViewer along with the following settings:
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution \
-XX:+PrintHeapAtGC -Xloggc:$TOMCAT_HOME/logs/gc-$(date +%s).log \
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M
In short, we're hoping someone might be able to help us ascertain what this
high cost thing is that we're seeing in the Java 8 collections. No matter what
settings we've tried or how many attempts at tuning we've made, we just can't
get PSYoungGen to run in less than 200 ms, and we're stumped.
A few GCs from each Java version are included below.
---------- Java 6 ----------
{Heap before GC invocations=612 (full 1):
PSYoungGen total 2090240K, used 2086987K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)
eden space 2083008K, 100% used [0x0000000780000000,0x00000007ff230000,0x00000007ff230000)
from space 7232K, 55% used [0x00000007ff8f0000,0x00000007ffcd2cc8,0x0000000800000000)
to space 6912K, 0% used [0x00000007ff230000,0x00000007ff230000,0x00000007ff8f0000)
PSOldGen total 3145728K, used 1438842K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)
object space 3145728K, 45% used [0x00000006c0000000,0x0000000717d1e8f8,0x0000000780000000)
PSPermGen total 1048576K, used 596997K [0x0000000680000000, 0x00000006c0000000, 0x00000006c0000000)
object space 1048576K, 56% used [0x0000000680000000,0x00000006a4701508,0x00000006c0000000)
1426.874: [GC
Desired survivor size 7077888 bytes, new threshold 15 (max 15)
[PSYoungGen: 2086987K->2558K(2089920K)] 3525829K->1442904K(5235648K), 0.0079930 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
Heap after GC invocations=612 (full 1):
PSYoungGen total 2089920K, used 2558K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)
eden space 2083008K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007ff230000)
from space 6912K, 37% used [0x00000007ff230000,0x00000007ff4af9e8,0x00000007ff8f0000)
to space 6912K, 0% used [0x00000007ff940000,0x00000007ff940000,0x0000000800000000)
PSOldGen total 3145728K, used 1440346K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)
object space 3145728K, 45% used [0x00000006c0000000,0x0000000717e969a0,0x0000000780000000)
PSPermGen total 1048576K, used 596997K [0x0000000680000000, 0x00000006c0000000, 0x00000006c0000000)
object space 1048576K, 56% used [0x0000000680000000,0x00000006a4701508,0x00000006c0000000)
}
{Heap before GC invocations=613 (full 1):
PSYoungGen total 2089920K, used 2085566K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)
eden space 2083008K, 100% used [0x0000000780000000,0x00000007ff230000,0x00000007ff230000)
from space 6912K, 37% used [0x00000007ff230000,0x00000007ff4af9e8,0x00000007ff8f0000)
to space 6912K, 0% used [0x00000007ff940000,0x00000007ff940000,0x0000000800000000)
PSOldGen total 3145728K, used 1440346K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)
object space 3145728K, 45% used [0x00000006c0000000,0x0000000717e969a0,0x0000000780000000)
PSPermGen total 1048576K, used 596997K [0x0000000680000000, 0x00000006c0000000, 0x00000006c0000000)
object space 1048576K, 56% used [0x0000000680000000,0x00000006a4701570,0x00000006c0000000)
1429.269: [GC
Desired survivor size 6815744 bytes, new threshold 15 (max 15)
[PSYoungGen: 2085566K->3488K(2090496K)] 3525912K->1443866K(5236224K), 0.0050560 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
Heap after GC invocations=613 (full 1):
PSYoungGen total 2090496K, used 3488K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)
eden space 2083584K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007ff2c0000)
from space 6912K, 50% used [0x00000007ff940000,0x00000007ffca8000,0x0000000800000000)
to space 6656K, 0% used [0x00000007ff2c0000,0x00000007ff2c0000,0x00000007ff940000)
PSOldGen total 3145728K, used 1440378K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)
object space 3145728K, 45% used [0x00000006c0000000,0x0000000717e9e9a0,0x0000000780000000)
PSPermGen total 1048576K, used 596997K [0x0000000680000000, 0x00000006c0000000, 0x00000006c0000000)
object space 1048576K, 56% used [0x0000000680000000,0x00000006a4701570,0x00000006c0000000)
}
{Heap before GC invocations=614 (full 1):
PSYoungGen total 2090496K, used 2086981K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)
eden space 2083584K, 99% used [0x0000000780000000,0x00000007ff2a9640,0x00000007ff2c0000)
from space 6912K, 50% used [0x00000007ff940000,0x00000007ffca8000,0x0000000800000000)
to space 6656K, 0% used [0x00000007ff2c0000,0x00000007ff2c0000,0x00000007ff940000)
PSOldGen total 3145728K, used 1440378K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)
object space 3145728K, 45% used [0x00000006c0000000,0x0000000717e9e9a0,0x0000000780000000)
PSPermGen total 1048576K, used 596997K [0x0000000680000000, 0x00000006c0000000, 0x00000006c0000000)
object space 1048576K, 56% used [0x0000000680000000,0x00000006a4701570,0x00000006c0000000)
1431.623: [GC
Desired survivor size 7012352 bytes, new threshold 15 (max 15)
[PSYoungGen: 2086981K->1344K(2090240K)] 3527359K->1441738K(5235968K), 0.0034930 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
Heap after GC invocations=614 (full 1):
PSYoungGen total 2090240K, used 1344K [0x0000000780000000, 0x0000000800000000, 0x0000000800000000)
eden space 2083584K, 0% used [0x0000000780000000,0x0000000780000000,0x00000007ff2c0000)
from space 6656K, 20% used [0x00000007ff2c0000,0x00000007ff410000,0x00000007ff940000)
to space 6848K, 0% used [0x00000007ff950000,0x00000007ff950000,0x0000000800000000)
PSOldGen total 3145728K, used 1440394K [0x00000006c0000000, 0x0000000780000000, 0x0000000780000000)
object space 3145728K, 45% used [0x00000006c0000000,0x0000000717ea29a0,0x0000000780000000)
PSPermGen total 1048576K, used 596997K [0x0000000680000000, 0x00000006c0000000, 0x00000006c0000000)
object space 1048576K, 56% used [0x0000000680000000,0x00000006a4701570,0x00000006c0000000)
}
---------- Java 8 ----------
{Heap before GC invocations=139 (full 2):
PSYoungGen total 2092032K, used 2088832K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 2086912K, 100% used [0x0000000740000000,0x00000007bf600000,0x00000007bf600000)
from space 5120K, 37% used [0x00000007bfb00000,0x00000007bfce0000,0x00000007c0000000)
to space 5120K, 0% used [0x00000007bf600000,0x00000007bf600000,0x00000007bfb00000)
ParOldGen total 4194304K, used 2114679K [0x0000000640000000, 0x0000000740000000, 0x0000000740000000)
object space 4194304K, 50% used [0x0000000640000000,0x00000006c111dc38,0x0000000740000000)
Metaspace used 58033K, capacity 58834K, committed 59056K, reserved 1101824K
class space used 6754K, capacity 6987K, committed 7088K, reserved 1048576K
1378.385: [GC (Allocation Failure)
Desired survivor size 4718592 bytes, new threshold 1 (max 15)
[PSYoungGen: 2088832K->1632K(2092032K)] 4203511K->2116327K(6286336K), 0.1997693 secs] [Times: user=0.22 sys=0.00, real=0.20 secs]
Heap after GC invocations=139 (full 2):
PSYoungGen total 2092032K, used 1632K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 2086912K, 0% used [0x0000000740000000,0x0000000740000000,0x00000007bf600000)
from space 5120K, 31% used [0x00000007bf600000,0x00000007bf798000,0x00000007bfb00000)
to space 4608K, 0% used [0x00000007bfb80000,0x00000007bfb80000,0x00000007c0000000)
ParOldGen total 4194304K, used 2114695K [0x0000000640000000, 0x0000000740000000, 0x0000000740000000)
object space 4194304K, 50% used [0x0000000640000000,0x00000006c1121c38,0x0000000740000000)
Metaspace used 58033K, capacity 58834K, committed 59056K, reserved 1101824K
class space used 6754K, capacity 6987K, committed 7088K, reserved 1048576K
}
{Heap before GC invocations=140 (full 2):
PSYoungGen total 2092032K, used 2088544K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 2086912K, 100% used [0x0000000740000000,0x00000007bf600000,0x00000007bf600000)
from space 5120K, 31% used [0x00000007bf600000,0x00000007bf798000,0x00000007bfb00000)
to space 4608K, 0% used [0x00000007bfb80000,0x00000007bfb80000,0x00000007c0000000)
ParOldGen total 4194304K, used 2114695K [0x0000000640000000, 0x0000000740000000, 0x0000000740000000)
object space 4194304K, 50% used [0x0000000640000000,0x00000006c1121c38,0x0000000740000000)
Metaspace used 58037K, capacity 58834K, committed 59056K, reserved 1101824K
class space used 6754K, capacity 6987K, committed 7088K, reserved 1048576K
1380.588: [GC (Allocation Failure)
Desired survivor size 4718592 bytes, new threshold 1 (max 15)
[PSYoungGen: 2088544K->1216K(2092544K)] 4203239K->2115935K(6286848K), 0.1992978 secs] [Times: user=0.22 sys=0.00, real=0.20 secs]
Heap after GC invocations=140 (full 2):
PSYoungGen total 2092544K, used 1216K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 2087936K, 0% used [0x0000000740000000,0x0000000740000000,0x00000007bf700000)
from space 4608K, 26% used [0x00000007bfb80000,0x00000007bfcb0000,0x00000007c0000000)
to space 4608K, 0% used [0x00000007bf700000,0x00000007bf700000,0x00000007bfb80000)
ParOldGen total 4194304K, used 2114719K [0x0000000640000000, 0x0000000740000000, 0x0000000740000000)
object space 4194304K, 50% used [0x0000000640000000,0x00000006c1127c38,0x0000000740000000)
Metaspace used 58037K, capacity 58834K, committed 59056K, reserved 1101824K
class space used 6754K, capacity 6987K, committed 7088K, reserved 1048576K
}
{Heap before GC invocations=141 (full 2):
PSYoungGen total 2092544K, used 2089152K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 2087936K, 100% used [0x0000000740000000,0x00000007bf700000,0x00000007bf700000)
from space 4608K, 26% used [0x00000007bfb80000,0x00000007bfcb0000,0x00000007c0000000)
to space 4608K, 0% used [0x00000007bf700000,0x00000007bf700000,0x00000007bfb80000)
ParOldGen total 4194304K, used 2114719K [0x0000000640000000, 0x0000000740000000, 0x0000000740000000)
object space 4194304K, 50% used [0x0000000640000000,0x00000006c1127c38,0x0000000740000000)
Metaspace used 58038K, capacity 58834K, committed 59056K, reserved 1101824K
class space used 6754K, capacity 6987K, committed 7088K, reserved 1048576K
1382.754: [GC (Allocation Failure)
Desired survivor size 4718592 bytes, new threshold 1 (max 15)
[PSYoungGen: 2089152K->2260K(2092544K)] 4203871K->2117011K(6286848K), 0.2010010 secs] [Times: user=0.23 sys=0.00, real=0.20 secs]
Heap after GC invocations=141 (full 2):
PSYoungGen total 2092544K, used 2260K [0x0000000740000000, 0x00000007c0000000, 0x00000007c0000000)
eden space 2087936K, 0% used [0x0000000740000000,0x0000000740000000,0x00000007bf700000)
from space 4608K, 49% used [0x00000007bf700000,0x00000007bf9351e0,0x00000007bfb80000)
to space 4608K, 0% used [0x00000007bfb80000,0x00000007bfb80000,0x00000007c0000000)
ParOldGen total 4194304K, used 2114751K [0x0000000640000000, 0x0000000740000000, 0x0000000740000000)
object space 4194304K, 50% used [0x0000000640000000,0x00000006c112fc38,0x0000000740000000)
Metaspace used 58038K, capacity 58834K, committed 59056K, reserved 1101824K
class space used 6754K, capacity 6987K, committed 7088K, reserved 1048576K
}
CONFIDENTIALITY NOTICE This message and any included attachments are from Cerner Corporation and are intended only for the addressee. The information contained in this message is confidential and may constitute inside or non-public information under international, federal, or state securities laws. Unauthorized forwarding, printing, copying, distribution, or use of such information is strictly prohibited and may be unlawful. If you are not the addressee, please promptly delete this message and notify the sender of the delivery error by e-mail or you may call Cerner's corporate offices in Kansas City, Missouri, U.S.A at (+1) (816)221-1024.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20160527/ace835b7/attachment-0001.html>
More information about the hotspot-gc-use
mailing list