Odd G1GC behavior on 8u91

[Vitaly Davidovich]

Hi Poonam,

On Thu, Aug 25, 2016 at 12:28 PM, Poonam Bajaj Parhar <
poonam.bajaj at oracle.com> wrote:

> Hello Vitaly,
>
> On 8/24/2016 3:55 PM, Vitaly Davidovich wrote:
>
>
>
> On Wed, Aug 24, 2016 at 6:29 PM, Poonam Bajaj Parhar <
> poonam.bajaj at oracle.com> wrote:
>
>> Also, do you see entries like "*[G1Ergonomics (Mixed GCs) do not start
>> mixed GCs, reason:" *in the GC logs which mean that the mixed GCs are
>> not happening due to some reason. What is the reason listed with these log
>> entries?
>>
> Hi Poonam,
>
> Yes, I do see a few those, but only very early in the process lifetime,
> and nowhere near the Full GCs.
>
> 2016-08-24T10:33:04.733+0000: 8.460: [SoftReference, 0 refs, 0.0010108
> secs]2016-08-24T10:33:04.734+0000: 8.461: [WeakReference, 383 refs,
> 0.0006608 secs]2016-08-24T10:33:04.735+0000: 8.462: [FinalReference, 4533
> refs, 0.0020491 secs]2016-08-24T10:33:04.737+0000: 8.464:
> [PhantomReference, 0 refs, 15 refs, 0.0011945 secs]2016-08-24T10:33:04.738+0000:
> 8.465: [JNI Weak Reference, 0.0000360 secs] 8.467: [G1Ergonomics (Mixed
> GCs) do not start mixed GCs, reason: concurrent cycle is about to start]
> 2016-08-24T10:35:22.846+0000: 146.574: [SoftReference, 0 refs, 0.0011450
> secs]2016-08-24T10:35:22.847+0000: 146.575: [WeakReference, 440 refs,
> 0.0006071 secs]2016-08-24T10:35:22.848+0000: 146.575: [FinalReference,
> 7100 refs, 0.0018074 secs]2016-08-24T10:35:22.850+0000: 146.577:
> [PhantomReference, 0 refs, 76 refs, 0.0013148 secs]2016-08-24T10:35:22.851+0000:
> 146.579: [JNI Weak Reference, 0.0000443 secs] 146.584: [G1Ergonomics (Mixed
> GCs) do not start mixed GCs, reason: concurrent cycle is about to start]
> 2016-08-24T10:35:56.507+0000: 180.234: [SoftReference, 0 refs, 0.0010184
> secs]2016-08-24T10:35:56.508+0000: 180.235: [WeakReference, 138 refs,
> 0.0006883 secs]2016-08-24T10:35:56.508+0000: 180.236: [FinalReference,
> 3682 refs, 0.0023152 secs]2016-08-24T10:35:56.511+0000: 180.238:
> [PhantomReference, 0 refs, 45 refs, 0.0012558 secs]2016-08-24T10:35:56.512+0000:
> 180.239: [JNI Weak Reference, 0.0000197 secs] 180.247: [G1Ergonomics (Mixed
> GCs) do not start mixed GCs, reason: concurrent cycle is about to start]
>
>
> The above entries should be okay.
>
> 2016-08-24T10:37:33.387+0000: 277.114: [SoftReference, 0 refs, 0.0010965
> secs]2016-08-24T10:37:33.388+0000: 277.115: [WeakReference, 5 refs,
> 0.0006378 secs]2016-08-24T10:37:33.388+0000: 277.116: [FinalReference,
> 3440 refs, 0.0028640 secs]2016-08-24T10:37:33.391+0000: 277.119:
> [PhantomReference, 0 refs, 0 refs, 0.0011392 secs]2016-08-24T10:37:33.392+0000:
> 277.120: [JNI Weak Reference, 0.0000148 secs] 277.130: [G1Ergonomics (Mixed
> GCs) do not start mixed GCs, reason: candidate old regions not available]
>
> If these appear only during the startup, I won't worry about these too.
>
> Do you see mixed GCs happening later during the run? If yes, then it's
> just that the mixed GCs are not quite enough to keep pace with the
> allocations/promotions into the old regions.
>
> To increase the number of old regions included into the cset, you could
> try increasing the value of
> *G1MixedGCLiveThresholdPercent.*
>
So as I mentioned in my earlier email today, we tried using IHOP=55
(instead of 75).  There are very long Object Copy and Finalize Marking
times now, although the heap cleanup is pretty good.  I didn't see any Full
GCs with that setting, but the very long Full GC pauses are just replaced
by extremely long Finalize Marking times (and fairly long Object Copy
times).

Thanks

>
> Thanks,
> Poonam
>
> Does that tell you anything?
>
>
>>
>> Thanks,
>> Poonam
>>
>> On 8/24/2016 3:18 PM, Jenny Zhang wrote:
>>
>> More comments about the questions
>>
>> Thanks
>> Jenny
>>
>> On 8/24/2016 11:43 AM, Vitaly Davidovich wrote:
>>
>> Right before the Full GC, ergonomics report a failure to expand the heap
>> due to an allocation request of 32 bytes.  Is this implying that a mutator
>> tried to allocate 32 bytes but couldn't? How do I reconcile that with
>> Eden+Survivor occupancy reported right above that?
>>
>> Yes, it means the mutator tries to allocate 32byte but can not get it.
>> Heap won't expand as it already reaches max heap.
>>
>> Do you see any humongous objects allocatoin?
>>
>>
>> Young gen is sized to 30GB, total heap is 96GB.  Allocation rate of the
>> application is roughly 1GB/s.  Am I correct in assuming that allocation is
>> outpacing concurrent marking, based on the above? What tunable(s) would you
>> advise to tweak to get G1 to keep up with the allocation rate? I'm ok
>> taking some throughput hit to mitigate 90s+ pauses.
>>
>> The entire log might give a better picture. Especially if the marking
>> cycle is triggered, how well the mixed gc cleans up the heap.
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://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/20160825/2619e581/attachment-0001.html>