Failing promption guarantee?

[Jon Masamitsu]

Jim,

Yes, the log entry is for a young collection that was started
but which could not be done because there was not enough room
in the tenured (old) generation to safely do the young collection.

You can see the young collection did not collect any garbage

 > 157148.797: [ParNew: 1100288K->1100288K(1100288K),

The before occupancy 1100288K is the same as the
after occupancy 1100288K.  That's followed by
the indication that a tenured collection was done.

157148.797: Tenured: 2014622K->1135456K(2936832K)

That only happens when there is not enough room in the
tenured gen to support the young gen collection (yes,
the promotion guarantee).

CMS is the low pause collector so would be helpful if you
were trying to avoid the long 17 sec pause.  Throughput
with the CMS collector is typically less so depending on
whether you want the low pause or the throughput, you
can make your choice.

You're using  UseParNewGC to do the parallel collection
in the young gen.  It's is perhaps more common to use
UseParallelGC to do the parallel collection.  Both collectors
do a parallel collection of the young gen and pretty
much perform equally well but some applications (because of
their allocation pattern) do better with one than the other.
It's something you can experiment with if you're interested.
The UseParallelGC collector has a relaxed promotion guarantee
so in situations where the heap is nearly full, it generally
performs better than UseParNewGC (at least in jdk5).

In the past I've seen lists of all bugs fixed in a release
in the release notes.  Sorry, I don't know if that is still
the practice.

I haven't heard anything about the relative stability of
jdk5_16 so I'm no help there.

Jon


James Nichols wrote:
> 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
> 
> 
> ------------------------------------------------------------------------
> 
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use