The GCLocker blues...

[Jon Masamitsu]

Peter,

Some of the cases that Tony points out have edens
with small amounts of used.  That would indicate that
a GC finished, the mutators were restarted and then
the GC-locker needed GC was requested.

Jon

On 6/27/2014 11:35 AM, Peter B. Kessler wrote:
> I thought there was code somewhere to address this in the case that 
> multiple threads requested collections (for whatever reason, not just 
> GC-locker).
>
> Something like: when the collection is requested, record the time (or 
> an epoch number like the collection count), and then when compare that 
> time (or epoch number) to the time (or epoch number) of the last 
> collection when the requested collection is processed.  If there's 
> been a collection since the request, assume the requested collection 
> is redundant.
>
> There it is: line 88 of
>
> http://hg.openjdk.java.net/jdk8u/jdk8u/hotspot/file/b67a3f81b630/src/share/vm/gc_implementation/shared/vmGCOperations.cpp
>
> VM_GC_Operation::skip_operation().  With a comment describing why it's 
> there.  Maybe it's not detailed enough to prevent an extra collection 
> in your situation?
>
>             ... peter
>
> On 06/27/14 09:41, Tony Printezis wrote:
>> Hi Jon,
>>
>> Great to hear from you! :-)
>>
>> I haven't actually tried running the test with JDK 6 (I could if it'd 
>> be helpful...).
>>
>> Yes, I know exactly what's going on. There's a race between one 
>> thread in jni_unlock() scheduling the GCLocker-initiated young GC 
>> (let's call it GC-L) and another thread also scheduling a young GC 
>> (let's call it GC-A) because it couldn't allocate due to the eden 
>> being full. Under certain circumstances, GC-A can happen first, with 
>> GC-L being scheduled and going ahead as soon as GC-A finishes.
>>
>> I'll open a CR and add a more detailed analysis to it.
>>
>> 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
>>>>
>>>
>>