Odd G1GC behavior on 8u91

Thu Aug 25 17:19:22 UTC 2016

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

> Hello Vitaly,
>
> On 8/25/2016 9:35 AM, Vitaly Davidovich wrote:
>
> 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).
>
>
> Yes, I was just reading that particular log that you had sent. The object
> copying times are very high.
>
> *      [Object Copy (ms): Min: 22450.6, Avg: 22615.0, Max: 22768.2, Diff:
> 317.5, Sum: 520143.9]*
>
> Could you try increasing the value of MaxTenuringThreshold or remove this
> option altogether. That would help in letting the objects die in the young
> regions itself and would avoid copying them to the old regions.
>
Yes, will try that -- the rationale makes sense.  I'm not entirely sure if
the survivors would actually die off or not, which would depend on their
lifetime and how it relates to GC frequency, but it's worth a shot.

Thanks

>
> Thanks,
> Poonam
>
>
>
> 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/44b12f19/attachment.html>