Odd G1GC behavior on 8u91

Thu Aug 25 16:28:49 UTC 2016

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 <mailto: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.

/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
>>     <mailto:hotspot-gc-use at openjdk.java.net>
>>     http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>     <http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use>
>
>
>     _______________________________________________
>     hotspot-gc-use mailing list
>     hotspot-gc-use at openjdk.java.net
>     <mailto:hotspot-gc-use at openjdk.java.net>
>     http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>     <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/511f8f4d/attachment.html>