The GCLocker blues...
Tony Printezis
tprintezis at twitter.com
Mon Jun 30 13:28:21 UTC 2014
Peter,
Yes, each GC VM op has the current GC counts and if by the time it runs
the GC counts are out-of-date, the op bails out in the prologue without
a safepoint. However, as I described on the CR, this doesn't work here.
By the time the thread gets the Heap_lock and reads the GC counts,
another GC has already happened. So, when the GC VM op runs, the GC
counts are up-to-date. The GC count protocol works for threads that are
trying to do allocations, given that those decisions are serialized
using the Heap_lock. However, the thread jni_unlock() is not part of
that protocol hence it is oblivious to those decisions.
Tony
On 6/27/14, 5:04 PM, Peter B. Kessler wrote:
> Right. VM_GC_Operation::skip_operation() could be made smarter. The
> current version just looks at the count of collections. There's lots
> of data available about why a collection was requested and again when
> it gets to the prologue. E.g., young generation occupancy. There's
> all the time in the world to make a good decision, relative to the
> time for the collection (if one happens) or the savings (if a
> collection is avoided).
>
> ... peter
>
> On 06/27/14 12:18, Jon Masamitsu wrote:
>> 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
>>>>>>
>>>>>
>>>>
>>
--
Tony Printezis | JVM/GC Engineer / VM Team | Twitter
@TonyPrintezis
tprintezis at twitter.com
More information about the hotspot-gc-dev
mailing list