How to read the output of +PrintTenuringDistribution

Question

I have gc log enabled with -XX:+PrintTenuringDistribution. But I'm quite confused with the tenuring distribution below.

From What I read, there are 10532656 bytes in age 1 (survived from 1 GC) in the first gc. In the second gc, 9178824 bytes in age 2 (survived from 2 GCs). This is fine since some objects died between the first and second GC.

But in the second GC, 16101552 bytes are in age 3 while only 14082976 bytes in age 2 in the first GC. I don't why this number is increasing. Shouldn't all bytes in age n come from age n-1 in the previous GC? Or I misinterpreted those numbers?

Thanks.

2013-10-19T19:46:30.244+0800: 169797.045: [GC2013-10-19T19:46:30.244+0800: 169797.045: [ParNew
Desired survivor size 87359488 bytes, new threshold 4 (max 4)
- age   1:   10532656 bytes,   10532656 total
- age   2:   14082976 bytes,   24615632 total
- age   3:   15155296 bytes,   39770928 total
- age   4:   13938272 bytes,   53709200 total
: 758515K->76697K(853376K), 0.0748620 secs] 4693076K->4021899K(6120832K), 0.0756370 secs] [Times: user=0.42 sys=0.00, real=0.07 secs]
2013-10-19T19:47:10.909+0800: 169837.710: [GC2013-10-19T19:47:10.909+0800: 169837.711: [ParNew
Desired survivor size 87359488 bytes, new threshold 4 (max 4)
- age   1:    9167144 bytes,    9167144 total
- age   2:    9178824 bytes,   18345968 total
- age   3:   16101552 bytes,   34447520 total
- age   4:   21369776 bytes,   55817296 total
: 759449K->63442K(853376K), 0.0776450 secs] 4704651K->4020310K(6120832K), 0.0783500 secs] [Times: user=0.43 sys=0.00, real=0.07 secs]

---

EDIT:

This has been confirmed as a bug in jvm itself due to a race condition in claiming the object.

The detailed discussion can be found here:

http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2013-October/001635.html

Answer 1

Discussion on OpenJDK mailing list ([email protected]) suggests what such abnormal tenuring distribution report is a result of race condition between threads undating per age counter.

Bug JDK-8027363 has been filled.

Excerpt from bug:

Here's the issue: In the code for copying a target object into the survivor space or into old gen, several threads may race to claim an object. In the case where the object's age is under the tenuring threshold, or if the older generation is not CMS, we will first copy the object then claim the object by swapping in the forwarding pointer to the copy. The other copies are discarded and the winning thread continues. The problem is that the age table is incremented by all of the threads racing to do the copying. The fix is that only the winner of the race should increment the age table to avoid multiple increments.

Answer 2

You're reading the log right, the problem lies on the tenuring threshold, which you have specified on 4.

The GC parameter “-XX:MaxTenuringThreshold” defines how many minor GC cycles 
an object can stay in the survivor spaces until it finally gets tenured to the 
old space.

So you have accumulating bytes from one scavenge to the next, since you can have memory sitting on a particular age for many GC rounds depending on your configured tenuring thresholds.

For instance, if you want to see that particular behavior you expected to see, set the threshold on 0.

-XX:MaxTenuringThreshold=0—Makes the full NewSize available to every NewGC cycle, 
and reduces the pause time by not evaluating tenured objects. Technically, 
this setting promotes all live objects to the older generation, rather 
than copying them