ParNew 4x slower under 1.7 vs 1.6?

Andrew Mulholland anmulholland at expedia.com
Fri Aug 9 15:48:37 PDT 2013


Hi

I've seen and read this thread from last year:
http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2012-November/001437.
html and have tried some of the options suggested in it, but to no avail.

We've been testing one of our web apps with 1.7.0_25 vs 1.6.0_43, and have
been seeing some very strange numbers for ParNew GC under 1.7.

We are fairly happy with the GC performance under 1.6, but wish to move to
1.7 following the EoL of 1.6.

I've attached (gzipped) GC logs from both 1.6 and 1.7 for analysis.

The logs are from the JVM startup, during which a script warms some caches
with a low level of load ­ and then the app is opened to a production
equivalent load for ~10 minutes.

The only difference between the runs, is the Java version. The results are
repeatable across multiple runs.

Additionally the performance remains similar if the JVM runs for a very
long time period (we've left a test load running for days under 1.7).


Under 1.6, we see:
- average ParNew pause times of ~100ms
   - with standard deviation of 0.12
- max of ~800ms
- cumulative total of ~11 seconds ParNew GC during the test run

Under 1.7 we see:
-  average ParNew pause times of ~440ms
    - with standard deviation of 0.26
- max of ~1600s
- cumulative total of ~40 seconds PewNew GC during the test run





Our application runs in a tomcat container and is run with JVM configured
as follows:

JAVA_OPTS="$JAVA_OPTS -Xms8192m -Xmx8192m"
JAVA_OPTS="$JAVA_OPTS -XX:MaxPermSize=256m -XX:NewRatio=2
-XX:SurvivorRatio=16 -Xss512k"
JAVA_OPTS="$JAVA_OPTS  -XX:+PrintCommandLineFlags -XX:PrintFLSStatistics=1
-XX:+PrintGCApplicationStoppedTime"
JAVA_OPTS="$JAVA_OPTS -Xloggc:${CATALINA_BASE}/logs/gc.log"
JAVA_OPTS="$JAVA_OPTS -verbose:gc -XX:+PrintGCTimeStamps
-XX:+PrintGCDetails"
JAVA_OPTS="$JAVA_OPTS -XX:+PrintTenuringDistribution"
JAVA_OPTS="$JAVA_OPTS -XX:+UseLinuxPosixThreadCPUClocks"
JAVA_OPTS="$JAVA_OPTS -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:+DisableExplicitGC"
JAVA_OPTS="$JAVA_OPTS -XX:+CMSConcurrentMTEnabled
-XX:+CMSScavengeBeforeRemark -XX:+CMSClassUnloadingEnabled"
JAVA_OPTS="$JAVA_OPTS -XX:CMSInitiatingOccupancyFraction=70"
JAVA_OPTS="$JAVA_OPTS -XX:+UseCompressedOops"

We run on Linux (Centos 6.3), on x86_64.
We have tried both on Physical hardware and Vms, and see the same
degradation on both.



I have also experimented with other settings such as the ones mentioned in
the other thread above, and whilst I can improve performance under 1.7 by
about 20%, it's still over 3x slower than under 1.6, which doesn't seem
right.
I have also tried removing most of the GC settings, and leaving just
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC, and see similar or worse results.

Adjusting heap size, or NewRatio also seems to make little effect on the
performance tooŠ 



Typical Collection under 1.6:
568.940: [GC Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 583884197
Max   Chunk Size: 583884197
Number of Blocks: 1
Av.  Block  Size: 583884197
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1721764
Max   Chunk Size: 1681920
Number of Blocks: 35
Av.  Block  Size: 49193
Tree      Height: 13

568.940: [ParNew
Desired survivor size 79527936 bytes, new threshold 15 (max 15)
- age   1:   15260904 bytes,   15260904 total
- age   2:    7430544 bytes,   22691448 total
- age   3:    7280688 bytes,   29972136 total
- age   4:    7580200 bytes,   37552336 total
- age   5:       3680 bytes,   37556016 total
- age   6:    7513296 bytes,   45069312 total
- age   7:    5490216 bytes,   50559528 total
- age   8:   10016024 bytes,   60575552 total
- age   9:    7684424 bytes,   68259976 total
- age  10:    3650576 bytes,   71910552 total
- age  11:    4543672 bytes,   76454224 total
: 2625089K->106222K(2640832K), 0.0986890 secs]
3651001K->1144739K(8233280K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 582295618
Max   Chunk Size: 582295618
Number of Blocks: 1
Av.  Block  Size: 582295618
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 1721764
Max   Chunk Size: 1681920
Number of Blocks: 35
Av.  Block  Size: 49193
Tree      Height: 13
, 0.0989930 secs] [Times: user=0.46 sys=0.02, real=0.10 secs]





Typical Collection under 1.7:

492.187: [GC Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 493494915
Max   Chunk Size: 493494915
Number of Blocks: 1
Av.  Block  Size: 493494915
Tree      Height: 1
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 2207447
Max   Chunk Size: 2178048
Number of Blocks: 45
Av.  Block  Size: 49054
Tree      Height: 11
492.187: [ParNew
Desired survivor size 79527936 bytes, new threshold 15 (max 15)
- age   1:   73826328 bytes,   73826328 total
: 2599315K->87426K(2640832K), 0.4153760 secs]
4331146K->1833474K(8233280K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 491592318
Max   Chunk Size: 491592318
Number of Blocks: 1
Av.  Block  Size: 491592318
Tree      Height: 1
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 2207447
Max   Chunk Size: 2178048
Number of Blocks: 45
Av.  Block  Size: 49054
Tree      Height: 11
, 0.4156130 secs] [Times: user=0.65 sys=0.02, real=0.42 secs]







Am I missing something obvious?





Thanks


Andrew


Andrew Mulholland
Operations Architect
Expedia Affiliate Network
p: +44 (0)20 7019 2927 | m: +44 (0)77 1585 4475
e: anmulholland at expedia.com

-------------- next part --------------
A non-text attachment was scrubbed...
Name: gc.log-1.7.0_25.gz
Type: application/x-gzip
Size: 24896 bytes
Desc: gc.log-1.7.0_25.gz
Url : http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20130809/7381fe52/gc.log-1.7.0_25-0001.gz 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: gc.log-1.6.0_43.gz
Type: application/x-gzip
Size: 35238 bytes
Desc: gc.log-1.6.0_43.gz
Url : http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20130809/7381fe52/gc.log-1.6.0_43-0001.gz 


More information about the hotspot-gc-use mailing list