The GCLocker blues...

[Monica Beckwith]

Hi Tony/ Jon -

AFAIK, this was observed and fixed a while back for G1. I will see if I 
can find the CR# for G1.

-Monica


On 6/27/14, 11:45 AM, Tony Printezis wrote:
> Jon,
>
> https://bugs.openjdk.java.net/browse/JDK-8048556
>
> Tony
>
> On 6/27/14, 11:25 AM, Jon Masamitsu wrote:
>> Tony,
>>
>> I don't recall talk within the GC group about this type of
>> problem.   I didn't find a CR that relates to that behavior.
>> If there is one, I don't think it is on anyone's radar.
>>
>> Can I infer that the problem does not occur in jdk6?
>>
>> Any theories on what's going on?
>>
>> Jon
>>
>>
>> On 6/27/2014 6:00 AM, Tony Printezis wrote:
>>> Hi all,
>>>
>>> (trying again from my Twitter address; moderator: feel free to 
>>> disregard the original I accidentally sent from my personal address)
>>>
>>> We have recently noticed an interesting problem which seems to 
>>> happen quite frequently under certain circumstances. Immediately 
>>> after a young GC, a second one happens which seems unnecessary given 
>>> that it starts with an empty or almost empty eden. Here's an example:
>>>
>>> {Heap before GC invocations=2 (full 0):
>>>  par new generation   total 471872K, used 433003K 
>>> [0x00000007bae00000, 0x00000007dae00000, 0x00000007dae00000)
>>>   eden space 419456K, 100% used [0x00000007bae00000, 
>>> 0x00000007d47a0000, 0x00000007d47a0000)
>>>   from space 52416K,  25% used [0x00000007d47a0000, 
>>> 0x00000007d54dacb0, 0x00000007d7ad0000)
>>>   to   space 52416K,   0% used [0x00000007d7ad0000, 
>>> 0x00000007d7ad0000, 0x00000007dae00000)
>>>  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
>>> 0x00000007fae00000, 0x00000007fae00000)
>>>    the space 524288K,   0% used [0x00000007dae00000, 
>>> 0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
>>>  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
>>> 0x00000007fc2c0000, 0x0000000800000000)
>>>    the space 21248K,  12% used [0x00000007fae00000, 
>>> 0x00000007fb07d7a0, 0x00000007fb07d800, 0x00000007fc2c0000)
>>> No shared spaces configured.
>>> 1.119: [GC (Allocation Failure)[ParNew: 433003K->15843K(471872K), 
>>> 0.0103090 secs] 433003K->15843K(996160K), 0.0103320 secs] [Times: 
>>> user=0.03 sys=0.00, real=0.01 secs]
>>> Heap after GC invocations=3 (full 0):
>>>  par new generation   total 471872K, used 15843K 
>>> [0x00000007bae00000, 0x00000007dae00000, 0x00000007dae00000)
>>>   eden space 419456K,   0% used [0x00000007bae00000, 
>>> 0x00000007bae00000, 0x00000007d47a0000)
>>>   from space 52416K,  30% used [0x00000007d7ad0000, 
>>> 0x00000007d8a48c88, 0x00000007dae00000)
>>>   to   space 52416K,   0% used [0x00000007d47a0000, 
>>> 0x00000007d47a0000, 0x00000007d7ad0000)
>>>  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
>>> 0x00000007fae00000, 0x00000007fae00000)
>>>    the space 524288K,   0% used [0x00000007dae00000, 
>>> 0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
>>>  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
>>> 0x00000007fc2c0000, 0x0000000800000000)
>>>    the space 21248K,  12% used [0x00000007fae00000, 
>>> 0x00000007fb07d7a0, 0x00000007fb07d800, 0x00000007fc2c0000)
>>> No shared spaces configured.
>>> }
>>> {Heap before GC invocations=3 (full 0):
>>>  par new generation   total 471872K, used 24002K 
>>> [0x00000007bae00000, 0x00000007dae00000, 0x00000007dae00000)
>>>   eden space 419456K,   1% used [0x00000007bae00000, 
>>> 0x00000007bb5f7c50, 0x00000007d47a0000)
>>>   from space 52416K,  30% used [0x00000007d7ad0000, 
>>> 0x00000007d8a48c88, 0x00000007dae00000)
>>>   to   space 52416K,   0% used [0x00000007d47a0000, 
>>> 0x00000007d47a0000, 0x00000007d7ad0000)
>>>  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
>>> 0x00000007fae00000, 0x00000007fae00000)
>>>    the space 524288K,   0% used [0x00000007dae00000, 
>>> 0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
>>>  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
>>> 0x00000007fc2c0000, 0x0000000800000000)
>>>    the space 21248K,  12% used [0x00000007fae00000, 
>>> 0x00000007fb07d7a0, 0x00000007fb07d800, 0x00000007fc2c0000)
>>> No shared spaces configured.
>>> 1.130: [GC (GCLocker Initiated GC)[ParNew: 24002K->12748K(471872K), 
>>> 0.0123930 secs] 24002K->12748K(996160K), 0.0124130 secs] [Times: 
>>> user=0.04 sys=0.01, real=0.01 secs]
>>> Heap after GC invocations=4 (full 0):
>>>  par new generation   total 471872K, used 12748K 
>>> [0x00000007bae00000, 0x00000007dae00000, 0x00000007dae00000)
>>>   eden space 419456K,   0% used [0x00000007bae00000, 
>>> 0x00000007bae00000, 0x00000007d47a0000)
>>>   from space 52416K,  24% used [0x00000007d47a0000, 
>>> 0x00000007d5413320, 0x00000007d7ad0000)
>>>   to   space 52416K,   0% used [0x00000007d7ad0000, 
>>> 0x00000007d7ad0000, 0x00000007dae00000)
>>>  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
>>> 0x00000007fae00000, 0x00000007fae00000)
>>>    the space 524288K,   0% used [0x00000007dae00000, 
>>> 0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
>>>  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
>>> 0x00000007fc2c0000, 0x0000000800000000)
>>>    the space 21248K,  12% used [0x00000007fae00000, 
>>> 0x00000007fb07d7a0, 0x00000007fb07d800, 0x00000007fc2c0000)
>>> No shared spaces configured.
>>> }
>>>
>>> Notice that:
>>>
>>> * The timestamp of the second GC (1.130) is almost equal to the 
>>> timestamp of the first GC plus the duration of the first GC (1.119 + 
>>> 0.0103320 = 1.1293). In this test young GCs normally happen at a 
>>> frequency of one every 100ms-110ms or so.
>>> * The eden at the start of the second GC is almost empty (1% 
>>> occupancy). We've also seen it very often with a completely empty eden.
>>> * (the big hint) The second GC is GClocker-initiated.
>>>
>>> This happens most often with ParNew (in some cases, more than 30% of 
>>> the GCs are those unnecessary ones) but also happens with ParallelGC 
>>> too but less frequently (maybe 1%-1.5% of the GCs are those 
>>> unnecessary ones). I was unable to reproduce it with G1.
>>>
>>> I can reproduce it with with latest JDK 7, JDK 8, and also the 
>>> latest hotspot-gc/hotspot workspace.
>>>
>>> Are you guys looking into this (and is there a CR?)? I have a small 
>>> test I can reproduce it with and a diagnosis / proposed fix(es) if 
>>> you're interested.
>>>
>>> Tony
>>>
>>
>