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 <vita...@gmail.com> wrote: > > > On Thu, Aug 25, 2016 at 12:54 PM, Poonam Bajaj Parhar < > poonam.ba...@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.ba...@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.ba...@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@openjdk.java.net >>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use >>>> >>>> >>>> >>>> _______________________________________________ >>>> hotspot-gc-use mailing list >>>> hotspot-gc-use@openjdk.java.net >>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use >>>> >>>> >>> >>> >> >> >
_______________________________________________ hotspot-gc-use mailing list hotspot-gc-use@openjdk.java.net http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
