Failing promption guarantee?

[Jones, Doug H]

Hi Jim,
 
Your log extract doesn't show how long normal collections of the tenured
area are taking. I suspect in the situation below it will revert to a
single-thread Stop-the-World collection, hence the 17 seconds.
 
The precursor of your problem is the line 'tenured generation   total
2936832K, used 2014622K' in the first heap dump - there is less than
NewSize free space remaining in tenured, so forcing the collection of
tenured before the scavenge. 
 
CMS GC will give you much shorter pauses during collection of the
tenured area, though as Jon M rightly says at the expense of a greater
use of resources. One other advantage of CMS GC is that it allows you to
control the percent full when a GC kicks in (so avoiding such 'promotion
failures'). Normally the JVM should dynamically adjust this, using a JIT
plus a bit to spare policy. But if your app suddenly creates a lots more
objects over a short period of time, it won't be able to anticipate
this.
 
 
Doug.


________________________________

	From: hotspot-gc-use-bounces at openjdk.java.net
[mailto:hotspot-gc-use-bounces at openjdk.java.net] On Behalf Of James
Nichols
	Sent: Tuesday, 15 July 2008 1:12 a.m.
	To: hotspot-gc-use at openjdk.java.net
	Subject: Failing promption guarantee?
	
	
	Hi,
	
	I have two questions.  
	
	I'm pretty sure I'm on the right track with this, but I'm
getting close to pushing out a new release and would really love an
extra set of eyes on this problem.  The first is that I think I might be
hitting the promotion guarantee, as shown by this GC output below.  As
you can see, both eden and from are 100% full, but I'm pretty sure that
it's all garbage, as evidenced by the precipitous drop in the young and
tenured generation.  Does the output for the actual GC saying ParNew
indicate that it was trying to do a young collection, but ended up doing
a full GC instead?  It also looks like CMS would've helped out in this
case.
	
	157148.797: [GC {Heap before gc invocations=545:
	 par new generation   total 1100288K, used 1100288K
[0x00002aaab21b0000, 0x00002aaafedb0000, 0x00002aaafedb0000)
	  eden space 943104K, 100% used [0x00002aaab21b0000,
0x00002aaaebab0000, 0x00002aaaebab0000)
	  from space 157184K, 100% used [0x00002aaaf5430000,
0x00002aaafedb0000, 0x00002aaafedb0000)
	  to   space 157184K,   0% used [0x00002aaaebab0000,
0x00002aaaebab0000, 0x00002aaaf5430000)
	 tenured generation   total 2936832K, used 2014622K
[0x00002aaafedb0000, 0x00002aabb21b0000, 0x00002aabb21b0000)
	   the space 2936832K,  68% used [0x00002aaafedb0000,
0x00002aab79d17ba0, 0x00002aab79d17c00, 0x00002aabb21b0000)
	 compacting perm gen  total 262144K, used 136065K
[0x00002aabb21b0000, 0x00002aabc21b0000, 0x00002aabc21b0000)
	   the space 262144K,  51% used [0x00002aabb21b0000,
0x00002aabba6906a0, 0x00002aabba690800, 0x00002aabc21b0000)
	No shared spaces configured.
	157148.797: [ParNew: 1100288K->1100288K(1100288K), 0.0000400
secs]157148.797: [Tenured: 2014622K->1135456K(2936832K), 17.1537650
secs] 3114910K->1135456K(4037120K)Heap after gc invocations=546:
	 par new generation   total 1100288K, used 0K
[0x00002aaab21b0000, 0x00002aaafedb0000, 0x00002aaafedb0000)
	  eden space 943104K,   0% used [0x00002aaab21b0000,
0x00002aaab21b0000, 0x00002aaaebab0000)
	  from space 157184K,   0% used [0x00002aaaf5430000,
0x00002aaaf5430000, 0x00002aaafedb0000)
	  to   space 157184K,   0% used [0x00002aaaebab0000,
0x00002aaaebab0000, 0x00002aaaf5430000)
	 tenured generation   total 2936832K, used 1135456K
[0x00002aaafedb0000, 0x00002aabb21b0000, 0x00002aabb21b0000)
	   the space 2936832K,  38% used [0x00002aaafedb0000,
0x00002aab44288078, 0x00002aab44288200, 0x00002aabb21b0000)
	 compacting perm gen  total 262144K, used 136065K
[0x00002aabb21b0000, 0x00002aabc21b0000, 0x00002aabc21b0000)
	   the space 262144K,  51% used [0x00002aabb21b0000,
0x00002aabba6906a0, 0x00002aabba690800, 0x00002aabc21b0000)
	No shared spaces configured.
	}
	, 17.1543400 secs]
	Total time for which application threads were stopped:
17.2148700 seconds
	
	
	Here are my JVM arguments: 
	
	JAVA_OPTS="-Xms4096m -Xmx4096m -XX:NewSize=1228M
-XX:MaxNewSize=1228M -XX:MaxTenuringThreshold=4 -XX:SurvivorRatio=6
-XX:+ScavengeBeforeFullGC -XX:PermSize=256M -XX:MaxPermSize=256M
-XX:+UseParNewGC -XX:ParallelGCThreads=3  -verbosegc
-XX:+DisableExplicitGC -XX:+PrintTenuringDistribution
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime
-XX:+PrintClassHistogram -Xloggc:/var/log/jboss/gc.dat
-Dsun.net.client.defaultConnectTimeout=10000"
	
	
	
	The second question is that I'm on JMV rev jdk1.5.0_12.  I see
that rev 16 is out.  Is there a way to get a list of any GC bug fixes in
this rev?  Also, has is there a way to gauge the stability of this rev
know that it has been in the wild for a while?  I'm just a little
nervous to make the change since I got burned pretty badly with like rev
08.
	
	Jim
	

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20080715/942dad13/attachment.html