How to read the output of +PrintTenuringDistribution

[Srinivas Ramakrishna]

Sorry, time for bed... I am not thinking straight...

Scratch the part about the old generation being CMS reducing the incidence
of the problem.
The age table is only incremented when the target goes to a survivor
space, so the probability of the race is independent of whether the old
generation is CMS or not.

I think the fix outlined above should take care of the bad accounting. And
would avoid (in extreme cases)
the adaprtive tenuring algorithm from being too pessimistic and using a
lower tenuring threshold than the
more accurate accounting would have yielded.

-- ramki



On Fri, Oct 25, 2013 at 12:46 AM, Srinivas Ramakrishna <ysr1729 at gmail.com>wrote:

> Never mind my question, born of a bit of confusion on my part.
>
> I think my explanation works in both cases, although the probability of
> the event is increased if the old gen collector is not
> CMS.
>
> 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.
>
> That should fix the problem you are seeing. The problem could be more
> acute in certain kinds of object graph structures, and also when the old
> generation is not CMS then the possibility of such races is slightly
> increased because it's present also when
> copying into the old generation.
>
> (I can't recall why we don't always first claim the object and then do the
> copying and then update the forwarding pointer, as is
> done when the target space is the CMS space. I'll let others reconstruct
> that reason, if that reason, probably a performance reason, is still
> relevant today....)
>
> -- ramki
>
>
>
> On Fri, Oct 25, 2013 at 12:27 AM, Srinivas Ramakrishna <ysr1729 at gmail.com>wrote:
>
>> Hi Ji --
>>
>> Are you using ParNew by itself without CMS in the old gen, or are you
>> using CMS in the old gen.
>> If the former, I have a possible explanation (although you will need to
>> evaluate the statistical probability
>> of an event based on the configuration and object demographics to
>> determine if it's plausible in your
>> case).
>>
>> If, however, you are using CMS in the old gen, then I don't have an
>> explanation.
>>
>> So, what is your config? :-)
>>
>> -- ramki
>>
>>
>>
>> On Thu, Oct 24, 2013 at 11:40 PM, Tao Mao <tao.mao at oracle.com> wrote:
>>
>>>  Hi Ji,
>>>
>>> From what you've reported, it definitely looks weird. Are these two GC's
>>> consecutive two GC's (i.e. no other GC/s in between)?
>>>
>>> Thanks.
>>> Tao
>>>
>>>
>>> On 10/24/13 9:45 PM, Ji Cheng wrote:
>>>
>>> Hello,
>>>
>>>  I have gc log enabled with -XX:+PrintTenuringDistribution. But I'm
>>> quite confused with the tenuring distribution below.
>>>
>>>  =============
>>>  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]
>>>  =============
>>>
>>>  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?
>>>
>>>  btw, the jvm version is 1.7.0_40.
>>>
>>>  Thanks.
>>>
>>>  Ji Cheng
>>>
>>>
>>> _______________________________________________
>>> hotspot-gc-use mailing listhotspot-gc-use at openjdk.java.nethttp://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>
>>>
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20131025/95f38f90/attachment.html