G1 - Mixed and Full GC's
Wolfgang Pedot
wolfgang.pedot at finkzeit.at
Thu Dec 15 19:03:05 UTC 2016
Hi,
thanks for correcting me Jenny, learned something new today.
Here is a short example from one of my servers (1.8.0_101) during normal
operation:
2016-12-15T14:19:42.749+0100: 961594.487: [GC pause (G1 Evacuation
Pause) (young) (initial-mark)
2016-12-15T14:19:42.955+0100: 961594.693: [GC
concurrent-root-region-scan-start]
2016-12-15T14:19:43.050+0100: 961594.788: [GC
concurrent-root-region-scan-end, 0.0947334 secs]
2016-12-15T14:19:43.050+0100: 961594.788: [GC concurrent-mark-start]
2016-12-15T14:19:46.094+0100: 961597.832: [GC concurrent-mark-end,
3.0445129 secs]
2016-12-15T14:19:46.112+0100: 961597.850: [GC remark
2016-12-15T14:19:46.112+0100: 961597.850: [Finalize Marking, 0.0023737
secs]
2016-12-15T14:19:46.114+0100: 961597.852: [GC ref-proc, 0.0095962 secs]
2016-12-15T14:19:46.124+0100: 961597.862: [Unloading
2016-12-15T14:19:46.131+0100: 961597.869: [System Dictionary Unloading,
0.1269161 secs]
2016-12-15T14:19:46.258+0100: 961597.996: [Parallel Unloading, 0.0361294
secs]
2016-12-15T14:19:46.294+0100: 961598.032: [Deallocate Metadata,
0.0017183 secs]
2016-12-15T14:19:46.296+0100: 961598.034: [String Deduplication Unlink,
0.0375517 secs], 0.2094571 secs], 0.2401670 secs]
2016-12-15T14:19:46.366+0100: 961598.104: [GC cleanup
2016-12-15T14:19:46.552+0100: 961598.290: [GC concurrent-cleanup-start]
2016-12-15T14:19:46.552+0100: 961598.290: [GC concurrent-cleanup-end,
0.0000160 secs]
2016-12-15T14:19:58.388+0100: 961610.126: [GC pause (G1 Evacuation
Pause) (young)
2016-12-15T14:19:59.684+0100: 961611.422: [GC pause (G1 Evacuation
Pause) (mixed)
2016-12-15T14:20:00.537+0100: 961612.275: [GC pause (G1 Evacuation
Pause) (mixed)
2016-12-15T14:20:01.023+0100: 961612.761: [GC pause (G1 Evacuation
Pause) (mixed)
2016-12-15T14:20:03.012+0100: 961614.750: [GC pause (G1 Evacuation
Pause) (mixed)
2016-12-15T14:20:04.339+0100: 961616.077: [GC pause (G1 Evacuation
Pause) (mixed)
2016-12-15T14:20:08.207+0100: 961619.945: [GC pause (G1 Evacuation
Pause) (mixed)
2016-12-15T14:20:12.424+0100: 961624.162: [GC pause (G1 Evacuation
Pause) (young)
Here is how I read the log-snippet:
Concurrent cycle was initiated at 14:19:42, REMARK was done at 14:19:46.
Mixed collects were started afterwards and the last one happened at
14:20:08, so the first chance to start a new concurrent cycle would have
been at 14:20:12.
If there are short lived small allocations during that time the
young/mixed-collects can get rid of them right away but new humongous
objects can not be collected until the next badge of mixed collects in
your JRE. I have no idea how long such a cycle takes on your system but
the longer it takes the higher the chance of an allocation failure
leading to a full-gc.
The eden space is drastically reduced during mixed collects (10-15% of
normal in my case) so that they happen more rapidly than pure young
collects, I guess if there are mainly humongous allocations happening
this would slow down the mixed collects.
regards
Wolfgang
Am 15.12.2016 um 18:28 schrieb yu.zhang at oracle.com:
> Hi,
>
> In the clean up cycle, about 1.6G is claimed. Those are cleaned
> because everything in the region is dead. It is possible those are
> regions for humongous objects.
>
> Wolfgang mentioned this already, in later jdk, certain type of
> humongous objects can be collected during young gc.
> To be more specific on the comments about what is collected during a
> mixed gc cycle, it is determined after REMARK, not the beginning of
> the marking cycle.
>
> About the question why mixed gc sees only 29M while full gc can claim
> 4041.8M, there could be several reasons:
> 1. -XX:G1MixedGCLiveThresholdPercent=85 is still too low. This means
> if the region is above 85% full, they are not considered to be
> candidate of mixed gc. But it might not be the reason, since full gc
> cleans up 4041.8M.
> 2. In your PrintAdaptiveSizePolicy output, there is information about
> how the collection set for mixed gc is decided. Can you post it?
> Though not likely, there is a chance it is not including some regions
> since the pause time goal is reached.
> 3. Full gc cleans everything, including classes and other references.
> In later jdk, classes are unloaded during marking cycle. But I am not
> sure if jdk7 has that.
> 4. As Wolfgang mentioned, maybe the allocation rate is too high for g1
> to keep up.
>
> Can you try:
> 1 increase the region size? It will not help the 15m allocation, but
> maybe helpful to reduce other humongous objects.
> 2. lower the -XX:InitiatingHeapOccupancyPercent=60 (default is 45) to
> introduce the marking cycle earlier
> 3. Depends on how long the marking cycle is, maybe increase the
> concurrent marking threads,
>
> Thanks
> Jenny
>
>
> On 12/15/2016 05:00 AM, Wolfgang Pedot wrote:
>> It is my understanding that what gets collected during a mixed cycle
>> is determined at the beginning of the cycle so if you have a high
>> allocation rate of short lived humongous objects you can fill up the
>> heap with stuff the concurrent cycle will not get rid of even though
>> they would be reclaimable. Newer JRE-Versions can reclaim humongous
>> regions during young generation collects so they can deal better with
>> them but I guess its still best to avoid humongous allocations if
>> easily possible.
>>
>> Can you check in your log how long G1 is usually doing mixed collects?
>>
>> -XX:+G1PrintRegionLivenessInfo may also be an interesting option, it
>> lets you see how many humongous objects are in your heap at the start
>> of a concurrent cycle and how full your regions are.
>>
>> regards
>> Wolfgang Pedot
>>
>> Am 15.12.2016 um 13:29 schrieb Gopal, Prasanna CWK:
>>>
>>> Hi Wolfgang
>>>
>>> Thanks for your reply. Yes I agree we have high CPU overhead. We
>>> have the following settings for CPU-Cores / GC Threads.
>>>
>>> virtualProcessorCount=48
>>>
>>> ParallelGCThreads=8
>>>
>>> *> AFAIR humongous regions are only collected during mixed/full GC
>>> in your version.*
>>>
>>> **This is my understanding as well, but I am not sure why these
>>> objects were not collected during Mixed GC cycles. The Mixed cycle
>>> is seeing only 29 MB as claimable, but the Full GC was able to claim
>>> 4041.8 MB within 100 ms
>>>
>>> *45349.970: [G1Ergonomics (Mixed GCs) do not start mixed GCs,
>>> reason: reclaimable percentage not over threshold, candidate old
>>> regions: 46 regions, reclaimable: 31277496 bytes (0.42 %),
>>> threshold: 10.00 %]*
>>>
>>> **
>>>
>>> **
>>>
>>> Regards
>>>
>>> Prasanna **
>>>
>>> -----Original Message-----
>>> From: hotspot-gc-use
>>> [mailto:hotspot-gc-use-bounces at openjdk.java.net] On Behalf Of
>>> Wolfgang Pedot
>>> Sent: 15 December 2016 12:10
>>> To: hotspot-gc-use at openjdk.java.net
>>> Subject: Re: G1 - Mixed and Full GC's
>>>
>>> Hi,
>>>
>>> not sure about my "expert"-ness but something caught my eye:
>>>
>>> you do have a pretty high GC overhead there (recent GC overhead:
>>> 30.14 %), it is possible that G1 can simply not keep up with your
>>> allocations and that leads to a full GC. How many CPU-cores does
>>> your machine have and how many GC threads are used?
>>>
>>> Can you determine the size of your humongous objects? Getting rid of
>>> those by increasing the region-size could help, AFAIR humongous
>>> regions are only collected during mixed/full GC in your version.
>>>
>>> regards
>>>
>>> Wolfgang Pedot
>>>
>>> Am 15.12.2016 um 10:44 schrieb Gopal, Prasanna CWK:
>>>
>>> >
>>>
>>> > Hi Experts
>>>
>>> >
>>>
>>> > We have one of our application running G1 with following
>>>
>>> > configuration
>>>
>>> >
>>>
>>> > -Xmx7G
>>>
>>> >
>>>
>>> > -Xms7G
>>>
>>> >
>>>
>>> > -XX:+UseG1GC
>>>
>>> >
>>>
>>> > -XX:+UnlockExperimentalVMOptions
>>>
>>> >
>>>
>>> > -XX:InitiatingHeapOccupancyPercent=60
>>>
>>> >
>>>
>>> > -XX:G1ReservePercent=20
>>>
>>> >
>>>
>>> > -XX:G1MixedGCLiveThresholdPercent=85
>>>
>>> >
>>>
>>> > -XX:MaxGCPauseMillis=500
>>>
>>> >
>>>
>>> > -XX:+ParallelRefProcEnabled
>>>
>>> >
>>>
>>> > -XX:+PrintAdaptiveSizePolicy
>>>
>>> >
>>>
>>> > -XX:+PrintHeapAtGC
>>>
>>> >
>>>
>>> > -XX:+PrintReferenceGC
>>>
>>> >
>>>
>>> > -XX:+PrintGCDateStamps
>>>
>>> >
>>>
>>> > -XX:+PrintTenuringDistribution
>>>
>>> >
>>>
>>> > -XX:+PrintGCApplicationConcurrentTime
>>>
>>> >
>>>
>>> > -XX:+PrintGCApplicationStoppedTime
>>>
>>> >
>>>
>>> > -Duser.timezone=America/Los_Angeles
>>>
>>> >
>>>
>>> > -d64 -Dserver
>>>
>>> >
>>>
>>> > JDK : jdk_7u40_x64 ( Yes we need to move to latest JDK)
>>>
>>> >
>>>
>>> > We are seeing the following behaviour
>>>
>>> >
>>>
>>> > End of a concurrent cycle
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:01.307-0500: 45342.193: Total time for which
>>>
>>> > application threads were stopped: 0.0189970 seconds
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:01.307-0500: 45342.193: Application time: 0.0001190
>>>
>>> > seconds
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:01.308-0500: 45342.193: *[GC cleanup
>>>
>>> > 5093M->3488M(7168M), 0.0075650 secs] *
>>>
>>> >
>>>
>>> > [Times: user=0.06 sys=0.00, real=0.01 secs]
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:01.315-0500: 45342.201: Total time for which
>>>
>>> > application threads were stopped: 0.0081250 seconds
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:01.315-0500: 45342.201: [GC
>>> concurrent-cleanup-start]
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:01.318-0500: 45342.203: [GC concurrent-cleanup-end,
>>>
>>> > 0.0022490 secs]
>>>
>>> >
>>>
>>> > After 8 Seconds, Minor GC kicks in and decides not to do any Mixed
>>>
>>> > GC’s
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:09.083-0500: 45349.969: [PhantomReference, 0 refs,
>>>
>>> > 0.0001880 secs]2016-12-14T12:59:09.083-0500: 45349.969: [JNI Weak
>>>
>>> > Reference, 0.0000050 secs] 45349.970: [G1Ergonomics (Heap Sizing)
>>>
>>> > attempt heap expansion, reason: recent GC overhead higher than
>>>
>>> > threshold after GC, recent GC overhead: 30.14 %, threshold: 10.00 %,
>>>
>>> > uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
>>>
>>> >
>>>
>>> > *45349.970: [G1Ergonomics (Concurrent Cycles) do not request
>>>
>>> > concurrent cycle initiation, reason: still doing mixed collections,
>>>
>>> > occupancy: 6926893056 bytes, allocation request: 0 bytes, threshold:
>>>
>>> > 4509715620 bytes (60.00 %), source: end of GC]*
>>>
>>> >
>>>
>>> > *45349.970: [G1Ergonomics (Mixed GCs) do not start mixed GCs, reason:
>>>
>>> > reclaimable percentage not over threshold, candidate old regions: 46
>>>
>>> > regions, reclaimable: 31277496 bytes (0.42 %), threshold: 10.00 %]*
>>>
>>> >
>>>
>>> > , 0.0765450 secs]
>>>
>>> >
>>>
>>> > [Parallel Time: 74.1 ms, GC Workers: 8]
>>>
>>> >
>>>
>>> > [GC Worker Start (ms): Min: 45349894.0, Avg: 45349894.1, Max:
>>>
>>> > 45349894.2, Diff: 0.3]
>>>
>>> >
>>>
>>> > [Ext Root Scanning (ms): Min: 4.3, Avg: 5.1, Max: 6.4, Diff:
>>>
>>> > 2.1, Sum: 41.2]
>>>
>>> >
>>>
>>> > [Update RS (ms): Min: 64.6, Avg: 66.2, Max: 67.1, Diff: 2.5,
>>>
>>> > Sum: 529.2]
>>>
>>> >
>>>
>>> > [Processed Buffers: Min: 324, Avg: 363.8, Max: 524, Diff:
>>>
>>> > 200, Sum: 2910]
>>>
>>> >
>>>
>>> > [Scan RS (ms): Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum:
>>>
>>> > 3.7]
>>>
>>> >
>>>
>>> > [Object Copy (ms): Min: 1.6, Avg: 2.0, Max: 2.3, Diff: 0.7,
>>> Sum:
>>>
>>> > 15.9]
>>>
>>> >
>>>
>>> > [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
>>> Sum:
>>>
>>> > 0.0]
>>>
>>> >
>>>
>>> > [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0,
>>>
>>> > Sum: 0.4]
>>>
>>> >
>>>
>>> > [GC Worker Total (ms): Min: 73.7, Avg: 73.8, Max: 73.9, Diff:
>>>
>>> > 0.2, Sum: 590.3]
>>>
>>> >
>>>
>>> > [GC Worker End (ms): Min: 45349967.8, Avg: 45349967.9, Max:
>>>
>>> > 45349967.9, Diff: 0.0]
>>>
>>> >
>>>
>>> > [Code Root Fixup: 0.0 ms]
>>>
>>> >
>>>
>>> > [Clear CT: 0.1 ms]
>>>
>>> >
>>>
>>> > [Other: 2.3 ms]
>>>
>>> >
>>>
>>> > [Choose CSet: 0.0 ms]
>>>
>>> >
>>>
>>> > [Ref Proc: 1.2 ms]
>>>
>>> >
>>>
>>> > [Ref Enq: 0.2 ms]
>>>
>>> >
>>>
>>> > [Free CSet: 0.6 ms]
>>>
>>> >
>>>
>>> > [Eden: 310.0M(1382.0M)->0.0B(352.0M) Survivors: 4096.0K->6144.0K
>>>
>>> > Heap: 6603.4M(7168.0M)->6297.9M(7168.0M)]
>>>
>>> >
>>>
>>> > Heap after GC invocations=4395 (full 207):
>>>
>>> >
>>>
>>> > garbage-first heap total 7340032K, used 6449092K
>>>
>>> > [0x000000063ae00000, 0x00000007fae00000, 0x00000007fae00000)
>>>
>>> >
>>>
>>> > region size 2048K, 3 young (6144K), 3 survivors (6144K)
>>>
>>> >
>>>
>>> > compacting perm gen total 77824K, used 77354K [0x00000007fae00000,
>>>
>>> > 0x00000007ffa00000, 0x0000000800000000)
>>>
>>> >
>>>
>>> > the space 77824K, 99% used [0x00000007fae00000,
>>>
>>> > 0x00000007ff98a840, 0x00000007ff98aa00, 0x00000007ffa00000)
>>>
>>> >
>>>
>>> > No shared spaces configured.
>>>
>>> >
>>>
>>> > }
>>>
>>> >
>>>
>>> > [Times: user=0.60 sys=0.00, real=0.08 secs]
>>>
>>> >
>>>
>>> > Immediately after this another concurrent cycle kicks in
>>>
>>> >
>>>
>>> > 45349.974: [G1Ergonomics (Concurrent Cycles) request concurrent cycle
>>>
>>> > initiation, reason: occupancy higher than threshold, occupancy:
>>>
>>> > 6943670272 bytes, allocation request: 15728656 bytes, threshold:
>>>
>>> > 4509715620 bytes (60.00 %), source: concurrent humongous allocation]
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:09.088-0500: 45349.974: Application time: 0.0004930
>>>
>>> > seconds
>>>
>>> >
>>>
>>> > 45349.974: [G1Ergonomics (Concurrent Cycles) request concurrent cycle
>>>
>>> > initiation, reason: requested by GC cause, GC cause: G1 Humongous
>>>
>>> > Allocation]
>>>
>>> >
>>>
>>> > Before the concurrent cycle can complete, Full GC kicks in
>>>
>>> >
>>>
>>> > 2016-12-14T12:59:09.195-0500: 45350.081: [*Full
>>>
>>> > GC2016-12-14T12:59:11.445-0500: 45352.331*: [SoftReference, 765 refs,
>>>
>>> > 0.0001920 secs]2016-12-14T12:59:11.445-0500: 45352.331:
>>>
>>> > [WeakReference, 2417 refs, 0.0004400
>>>
>>> > secs]2016-12-14T12:59:11.446-0500: 45352.331: [FinalReference, 898
>>>
>>> > refs, 0.0001680 secs]2016-12-14T12:59:11.446-0500: 45352.332:
>>>
>>> > [PhantomReference, 10 refs, 0.0000060
>>>
>>> > secs]2016-12-14T12:59:11.446-0500: 45352.332: [JNI Weak Reference,
>>>
>>> > 0.0000190 secs] 6557M->2515M(7168M), 6.1312980 secs]
>>>
>>> >
>>>
>>> > [Eden: 2048.0K(348.0M)->0.0B(3070.0M) Survivors: 10.0M->0.0B Heap/:
>>>
>>> > 6557.1M(7168.0M)->2515.3M(7168.0M)]/
>>>
>>> >
>>>
>>> > It will be helpful for us to understand,
>>>
>>> >
>>>
>>> > 1)Why If Full GC can clean up nearly 4 GB (:
>>>
>>> > 6557.1M(7168.0M)->2515.3M(7168.0M)]) , why didn’t the mixed GC kicked
>>>
>>> > in earlier ?. Does this mean all our old regions are tightly packed
>>>
>>> > (greater than G1MixedGCLiveThresholdPercent=85 ) ?
>>>
>>> >
>>>
>>> > 2)We also see , high amount of Humongous object allocation. Could it
>>>
>>> > be the case that Only Full GC’s can remove the Humongous objects ?
>>>
>>> >
>>>
>>> > 3)Is there any other tuning parameters we can use to mitigate this
>>>
>>> > scenario ?
>>>
>>> >
>>>
>>> > Please do let me know, if you need any more information. Thanks in
>>>
>>> > advance for your help.
>>>
>>> >
>>>
>>> > Regards
>>>
>>> >
>>>
>>> > Prasanna
>>>
>>> >
>>>
>>> > This message may contain information that is confidential or
>>>
>>> > privileged. If you are not the intended recipient, please advise the
>>>
>>> > sender immediately and delete this message. See
>>>
>>> > http://www.blackrock.com/corporate/en-us/compliance/email-disclaimers
>>>
>>> > for further information. Please refer to
>>>
>>> > http://www.blackrock.com/corporate/en-us/compliance/privacy-policy
>>> for
>>>
>>> > more information about BlackRock’s Privacy Policy.
>>>
>>> >
>>>
>>> > BlackRock Advisors (UK) Limited and BlackRock Investment Management
>>>
>>> > (UK) Limited are authorised and regulated by the Financial Conduct
>>>
>>> > Authority. Registered in England No. 796793 and No. 2020394
>>>
>>> > respectively. BlackRock Life Limited is authorised by the Prudential
>>>
>>> > Regulation Authority and regulated by the Financial Conduct Authority
>>>
>>> > and the Prudential Regulation Authority. Registered in England No.
>>>
>>> > 2223202. Registered Offices: 12 Throgmorton Avenue, London EC2N 2DL.
>>>
>>> > BlackRock International Limited is authorised and regulated by the
>>>
>>> > Financial Conduct Authority and is a registered investment adviser
>>>
>>> > with the Securities and Exchange Commission (SEC). Registered in
>>>
>>> > Scotland No. SC160821. Registered Office: Exchange Place One, 1
>>> Semple
>>>
>>> > Street, Edinburgh EH3 8BL.
>>>
>>> >
>>>
>>> > For a list of BlackRock's office addresses worldwide, see
>>>
>>> > http://www.blackrock.com/corporate/en-us/about-us/contacts-locations.
>>>
>>> >
>>>
>>> > © 2016 BlackRock, Inc. All rights reserved.
>>>
>>> >
>>>
>>> >
>>>
>>> >
>>>
>>> > _______________________________________________
>>>
>>> > hotspot-gc-use mailing list
>>>
>>> > hotspot-gc-use at openjdk.java.net
>>> <mailto:hotspot-gc-use at openjdk.java.net>
>>>
>>> >
>>> https://urldefense.proofpoint.com/v2/url?u=http-3A__mail.openjdk.java.
>>>
>>> > net_mailman_listinfo_hotspot-2Dgc-2Duse&d=DgIF-g&c=zUO0BtkCe66yJvAZ4cA
>>>
>>> > vZg&r=zRhnqN6xuCQh8NZ-MtoiYBMlItU6r8UBO9AjZ3c3DEY&m=HPr1mqYayxpa0G_rtP
>>>
>>> > wLGWFkvYKVz9FdwvF7z1SkS3c&s=5p47SWF52v-EjwMvGiabOcfqPVCmBe99A6OImV1EP8
>>>
>>> > Y&e=
>>>
>>> _______________________________________________
>>>
>>> hotspot-gc-use mailing list
>>>
>>> hotspot-gc-use at openjdk.java.net
>>> <mailto:hotspot-gc-use at openjdk.java.net>
>>>
>>> https://urldefense.proofpoint.com/v2/url?u=http-3A__mail.openjdk.java.net_mailman_listinfo_hotspot-2Dgc-2Duse&d=DgIF-g&c=zUO0BtkCe66yJvAZ4cAvZg&r=zRhnqN6xuCQh8NZ-MtoiYBMlItU6r8UBO9AjZ3c3DEY&m=HPr1mqYayxpa0G_rtPwLGWFkvYKVz9FdwvF7z1SkS3c&s=5p47SWF52v-EjwMvGiabOcfqPVCmBe99A6OImV1EP8Y&e=
>>>
>>>
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
More information about the hotspot-gc-use
mailing list