JDK-6859722 : 6u14 Frequent ParNew promotion failure degrades performance
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 6u14
  • Priority: P2
  • Status: Closed
  • Resolution: Duplicate
  • OS: linux_redhat_5.0
  • CPU: x86
  • Submitted: 2009-07-13
  • Updated: 2010-07-29
  • Resolved: 2009-09-23
Related Reports
Duplicate :  
Relates :  
Relates :  
Relates :  
Description
6u14 on linux RHEL5, 4 CPU

While performing TPC-W type performance tests on JBoss, customer saw
frequent (few times in a minute) ParNew (promotion failed) followed by
non-concurrent CMS collection.

2529.623: [GC 2529.625: [ParNew (promotion failed): 707840K->707840K(707840K), 1.5373420 s
ecs]2531.163: [CMS: 737871K->584810K(1773568K), 3.2199960 secs] 1440170K->584810K(2481408K
), [CMS Perm : 44592K->44592K(131072K)], 4.7603810 secs] [Times: user=5.36 sys=0.75, real=
4.76 secs]
2539.185: [GC 2539.187: [ParNew: 629248K->78592K(707840K), 0.5736050 secs] 1214058K->68965
2K(2481408K), 0.5765820 secs] [Times: user=1.01 sys=0.02, real=0.58 secs]
2550.902: [GC 2550.904: [ParNew: 707840K->78591K(707840K), 0.7277150 secs] 1318900K->74039
6K(2481408K), 0.7307500 secs] [Times: user=1.30 sys=0.02, real=0.73 secs]
2556.513: [GC 2556.515: [ParNew: 707839K->78591K(707840K), 0.5953710 secs] 1369644K->79554
6K(2481408K), 0.5982010 secs] [Times: user=1.23 sys=0.03, real=0.60 secs]
2561.900: [GC 2561.901: [ParNew (promotion failed): 707806K->707806K(707840K), 1.7771810 s
ecs]2563.679: [CMS: 747493K->674555K(1773568K), 3.6702100 secs] 1424761K->674555K(2481408K
), [CMS Perm : 44685K->44685K(131072K)], 5.4501590 secs] [Times: user=6.21 sys=0.75, real=
5.46 secs]
2571.632: [GC 2571.634: [ParNew: 629248K->78592K(707840K), 0.7608740 secs] 1303803K->78993
9K(2481408K), 0.7641500 secs] [Times: user=1.31 sys=0.02, real=0.76 secs]
2581.897: [GC 2581.899: [ParNew: 707840K->78592K(707840K), 0.7720950 secs] 1419187K->86781
8K(2481408K), 0.7747690 secs] [Times: user=1.53 sys=0.02, real=0.78 secs]
2586.510: [GC 2586.511: [ParNew (promotion failed): 707840K->707839K(707840K), 1.4360230 s
ecs]2587.948: [CMS: 811594K->595802K(1773568K), 2.9612200 secs] 1497066K->595802K(2481408K
), [CMS Perm : 44696K->44696K(131072K)], 4.3999680 secs] [Times: user=5.08 sys=0.59, real=
4.40 secs]

The CMS heap might be badly fragmented.

We also see CMS heap usage is relatively smaller than its total size.

[CMS: 811594K->595802K(1773568K)

If the promotion failure or ParNew failure results in Full GC, foreground
CMS may perform compaction which would reduce fragmentation, but it does
look it is not done (or done well) for this pattern.

The pattern begins around 40 minutes (2400 seconds) since VM start and last
until 1hour and 3 minutes.  There were three Full GC around 1 hour since 
start.


The web application uses servlets and JSP and about 2500 clients performs
operation per second.  There are 18000 clients in total, but there some
pauses between operations.

They saw similar symptom with an EJB app and the pattern appears when the
# of clients reaches certain number, for this case 15500.

Here is the JVM options:
-server -Xmn768m -Xms2500m -Xmx2500m
-Xss128k -XX:PermSize=128m
-XX:MaxPermSize=128m
-XX:+UseConcMarkSweepGC
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=32
-Dsun.rmi.dgc.client.gcInterval=3600000
-Dsun.rmi.dgc.server.gcInterval=3600000
-Djava.net.preferIPv4Stack=true
-XX:+CMSClassUnloadingEnabled
-XX:+UseCMSInitiatingOccupancyOnly
-XX:CMSInitiatingOccupancyFraction=90
-XX:+ExplicitGCInvokesConcurrent

ParNew/CMS should be improved not to cause this performance degradation
due to frequent promotion failures.
.

Comments
EVALUATION This bug will be fixed under 6631166. It should be closed as a dup of 6631166.
23-09-2009