Odd G1GC behavior on 8u91

Thu Aug 25 17:23:32 UTC 2016

Forgot to mention that besides the long Object Copy time, the extremely
long Finalize Marking duration is also quite puzzling.  It may be related
to https://bugs.openjdk.java.net/browse/JDK-8057003, but I'm not sure yet.

On Thu, Aug 25, 2016 at 1:19 PM, Vitaly Davidovich <vitalyd at gmail.com>
wrote:

>
>
> 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/f477d88a/attachment-0001.html>