G1-GC - Full GC [humongous allocation request failed]
yu.zhang at oracle.com
yu.zhang at oracle.com
Fri Oct 7 15:52:01 UTC 2016
Prasanna,
In addition to what Vitaly said, I have some comments about your question:
1) Humongus allocation request for 72 mb failed, from the logs we can
also see we have free space of around 3 GB. Does this means , our
application is encountering high amount of fragmentation ?.
It is possible. What it means is g1 can not find 36 consecutive regions
for that 72 mb object.
I agree the ReservePercent=40 is too high, but that should not prevent
allocating to the old gen. G1 tries to honor ReservePercent.
2)2) Does tunning the gc params to make sure Mixed GC happens more ,
will help in resolving such Full GC’s ?
If you can not move to jdk8, in jdk7 the default for parameter
G1MixedGCLiveThresholdPercent is 65 (changed to 85 in jdk8). That is too
low for most workloads. You can increase that so that more old regions
will be treat as candidate for mixed gc.
3) Is there –XX:Print* flag which can tell us how many old gen and
humongous regions we have (other than looking at [G1 Ergonomics]
output , which sometimes gives old gen region count) ?
You get that count in jdk9, not jdk7.
One basic requirement for using G1GC, you need to give the pause time
goal. G1 uses that for sizing young/old gen. The default is 200ms.
Thanks
Jenny
On 10/07/2016 05:48 AM, Vitaly Davidovich wrote:
> Hi Prasanna,
>
> First suggestion - move to latest Java 8. G1 saw a lot of
> improvements in 8, and 7 is EOL of course.
>
> Humongous allocations require contiguous regions to satisfy the
> allocation, and are done directly out of old gen. You're reserving
> 40% of heap to handle overflow(G1ReservePercent) - why? I believe that
> reserve is only for mitigating to-space exhaustion, which is during
> evacuation only - they won't be available for humongous allocations
> (someone can correct me if that's wrong).
>
> Heap expansion fails because you're already at the limit given 40% is
> reserved.
>
> Again, I think you'll get more help here if you move to one of the
> latest Java 8 releases.
>
> On Friday, October 7, 2016, Gopal, Prasanna CWK
> <prasanna.gopal at blackrock.com
> <javascript:_e(%7B%7D,'cvml','prasanna.gopal at blackrock.com');>> wrote:
>
> Hi All
>
> We have one of our application with the following settings
>
> JVM : jdk_7u40_x64 ( we are in process of migrating to latest
> Jdk 7 family )
>
> -XX:MaxPermSize=512m
>
> -XX:+UseG1GC
>
> -XX:G1ReservePercent=40
>
> -XX:ConcGCThreads=14
>
> -XX:+PrintGCDateStamps
>
> -XX:+PrintTenuringDistribution
>
> -XX:+PrintGCApplicationConcurrentTime
>
> -XX:+PrintGCApplicationStoppedTime
>
> -XX:+PrintAdaptiveSizePolicy
>
> -XX:+PrintHeapAtGC
>
> -XX:+PrintReferenceGC
>
> -Xmx5120M
>
> -Xms5120M
>
> From our GC logs , we can see our application is going Full GC due
> to humongous allocation failure. But from the logs we can see
>
> GC logs
>
> =======
>
> 2016-10-07T02:37:14.978-0400: 71150.009: Total time for which
> application threads were stopped: 0.0137870 seconds
>
> 71150.399: [G1Ergonomics (Heap Sizing) attempt heap expansion,
> reason: humongous allocation request failed, allocation request:
> 75497488 bytes]
>
> 71150.399: [G1Ergonomics (Heap Sizing) expand the heap, requested
> expansion amount: *75497472* bytes, attempted expansion amount:
> 75497472 bytes]
>
> 71150.399: [G1Ergonomics (Heap Sizing) did not expand the heap,
> reason: heap expansion operation failed]
>
> 2016-10-07T02:37:15.367-0400: 71150.399: Application time:
> 0.3898050 seconds
>
> 71150.401: [G1Ergonomics (Heap Sizing) attempt heap expansion,
> reason: humongous allocation request failed, allocation request:
> 75497488 bytes]
>
> 71150.401: [G1Ergonomics (Heap Sizing) expand the heap, requested
> expansion amount: 75497472 bytes, attempted expansion amount:
> 75497472 bytes]
>
> 71150.401: [G1Ergonomics (Heap Sizing) did not expand the heap,
> reason: heap expansion operation failed]
>
> {Heap before GC invocations=55428 (full 4):
>
> garbage-first heap total 5242880K, used 1900903K
> [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)
>
> region size 2048K, 197 young (403456K), 14 survivors (28672K)
>
> compacting perm gen total 96256K, used 94313K
> [0x00000007e0000000, 0x00000007e5e00000, 0x0000000800000000)
>
> the space 96256K, 97% used [0x00000007e0000000,
> 0x00000007e5c1a700, 0x00000007e5c1a800, 0x00000007e5e00000)
>
> No shared spaces configured.
>
> 2016-10-07T02:37:15.369-0400: 71150.401: [GC pause (young)
>
> Desired survivor size 108003328 bytes, new threshold 15 (max 15)
>
> - age 1: 2362400 bytes, 2362400 total
>
> - age 2: 393128 bytes, 2755528 total
>
> - age 3: 1086824 bytes, 3842352 total
>
> - age 4: 1086528 bytes, 4928880 total
>
> - age 5: 1075480 bytes, 6004360 total
>
> - age 6: 1126736 bytes, 7131096 total
>
> - age 7: 1153072 bytes, 8284168 total
>
> - age 8: 1145832 bytes, 9430000 total
>
> - age 9: 1217904 bytes, 10647904 total
>
> - age 10: 1188384 bytes, 11836288 total
>
> - age 11: 1212456 bytes, 13048744 total
>
> - age 12: 1263960 bytes, 14312704 total
>
> - age 13: 4816 bytes, 14317520 total
>
> - age 14: 88952 bytes, 14406472 total
>
> - age 15: 7408 bytes, 14413880 total
>
> 71150.401: [G1Ergonomics (CSet Construction) start choosing CSet,
> _pending_cards: 149101, predicted base time: 16.35 ms, remaining
> time: 183.65 ms, target pause time: 200.00 ms]
>
> 71150.401: [G1Ergonomics (CSet Construction) add young regions to
> CSet, eden: 183 regions, survivors: 14 regions, predicted young
> region time: 3.45 ms]
>
> 71150.401: [G1Ergonomics (CSet Construction) finish choosing CSet,
> eden: 183 regions, survivors: 14 regions, old: 0 regions,
> predicted pause time: 19.80 ms, target pause time: 200.00 ms]
>
> 2016-10-07T02:37:15.410-0400: 71150.442: [SoftReference, 0 refs,
> 0.0000460 secs]2016-10-07T02:37:15.410-0400: 71150.442:
> [WeakReference, 1 refs, 0.0000050
> secs]2016-10-07T02:37:15.410-0400: 71150.442: [FinalReference, 4
> refs, 0.0000210 secs]2016-10-07T02:37:15.410-0400: 71150.442:
> [PhantomReference, 0 refs, 0.0000040
> secs]2016-10-07T02:37:15.410-0400: 71150.442: [JNI Weak Reference,
> 0.0000050 secs], 0.0428440 secs]
>
> [Parallel Time: 40.0 ms, GC Workers: 16]
>
> [GC Worker Start (ms): Min: 71150401.6, Avg: 71150401.8, Max:
> 71150401.9, Diff: 0.4]
>
> [Ext Root Scanning (ms): Min: 3.1, Avg: 3.9, Max: 8.4, Diff: 5.3,
> Sum: 62.1]
>
> [Update RS (ms): Min: 14.8, Avg: 19.0, Max: 19.8, Diff: 5.0, Sum:
> 304.3]
>
> [Processed Buffers: Min: 21, Avg: 37.6, Max: 86, Diff: 65,
> Sum: 601]
>
> [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.9]
>
> [Object Copy (ms): Min: 16.5, Avg: 16.6, Max: 16.8, Diff: 0.3,
> Sum: 266.3]
>
> [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.1,
> Sum: 0.7]
>
> [GC Worker Total (ms): Min: 39.5, Avg: 39.6, Max: 39.9, Diff: 0.4,
> Sum: 634.4]
>
> [GC Worker End (ms): Min: 71150441.4, Avg: 71150441.4, Max:
> 71150441.5, Diff: 0.1]
>
> [Code Root Fixup: 0.0 ms]
>
> [Clear CT: 0.2 ms]
>
> [Other: 2.7 ms]
>
> [Choose CSet: 0.0 ms]
>
> [Ref Proc: 0.3 ms]
>
> [Ref Enq: 0.0 ms]
>
> [Free CSet: 1.3 ms]
>
> [Eden: 366.0M(1616.0M)->0.0B(1384.0M) Survivors: 28.0M->104.0M
> Heap: 1856.6M(5120.0M)->1568.8M(5120.0M)]
>
> Heap after GC invocations=55429 (full 4):
>
> garbage-first heap total 5242880K, used 1606459K
> [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)
>
> region size 2048K, 52 young (106496K), 52 survivors (106496K)
>
> compacting perm gen total 96256K, used 94313K
> [0x00000007e0000000, 0x00000007e5e00000, 0x0000000800000000)
>
> the space 96256K, 97% used [0x00000007e0000000,
> 0x00000007e5c1a700, 0x00000007e5c1a800, 0x00000007e5e00000)
>
> No shared spaces configured.
>
> }
>
> [Times: user=0.64 sys=0.00, real=0.04 secs]
>
> 71150.444: [G1Ergonomics (Heap Sizing) attempt heap expansion,
> reason: humongous allocation request failed, allocation request:
> 75497488 bytes]
>
> 71150.444: [G1Ergonomics (Heap Sizing) expand the heap, requested
> expansion amount: 69206016 bytes, attempted expansion amount:
> 69206016 bytes]
>
> 71150.444: [G1Ergonomics (Heap Sizing) did not expand the heap,
> reason: heap expansion operation failed]
>
> 2016-10-07T02:37:15.412-0400: 71150.444: Total time for which
> application threads were stopped: 0.0448480 seconds
>
> 2016-10-07T02:37:15.412-0400: 71150.444: Application time:
> 0.0000500 seconds
>
> 71150.445: [G1Ergonomics (Heap Sizing) attempt heap expansion,
> reason: humongous allocation request failed, allocation request:
> 75497488 bytes]
>
> 71150.445: [G1Ergonomics (Heap Sizing) expand the heap, requested
> expansion amount: 69206016 bytes, attempted expansion amount:
> 69206016 bytes]
>
> 71150.445: [G1Ergonomics (Heap Sizing) did not expand the heap,
> reason: heap expansion operation failed]
>
> 71150.445: [G1Ergonomics (Heap Sizing) attempt heap expansion,
> reason: allocation request failed, allocation request: 75497488 bytes]
>
> 71150.445: [G1Ergonomics (Heap Sizing) expand the heap, requested
> expansion amount: 75497488 bytes, attempted expansion amount:
> 77594624 bytes]
>
> 71150.445: [G1Ergonomics (Heap Sizing) did not expand the heap,
> reason: heap expansion operation failed]
>
> {Heap before GC invocations=55429 (full 4):
>
> garbage-first heap total 5242880K, used 1606459K
> [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)
>
> region size 2048K, 53 young (108544K), 52 survivors (106496K)
>
> compacting perm gen total 96256K, used 94313K
> [0x00000007e0000000, 0x00000007e5e00000, 0x0000000800000000)
>
> the space 96256K, 97% used [0x00000007e0000000,
> 0x00000007e5c1a700, 0x00000007e5c1a800, 0x00000007e5e00000)
>
> No shared spaces configured.
>
> 2016-10-07T02:37:15.414-0400: 71150.445: [Full
> GC2016-10-07T02:37:16.337-0400: 71151.368: [SoftReference, 86
> refs, 0.0000720 secs]2016-10-07T02:37:16.337-0400: 71151.368:
> [WeakReference, 1760 refs, 0.0002980
> secs]2016-10-07T02:37:16.337-0400: 71151.369: [FinalReference,
> 1201 refs, 0.0002080 secs]2016-10-07T02:37:16.337-0400: 71151.369:
> [PhantomReference, 0 refs, 0.0000030
> secs]2016-10-07T02:37:16.337-0400: 71151.369: [JNI Weak Reference,
> 0.0000080 secs] 1568M->915M(5120M), 2.6880870 secs]
>
> 60 refs, 0.0002980 secs]2016-10-07T02:37:16.337-0400: 71151.369:
> [FinalReference, 1201 refs, 0.0002080
> secs]2016-10-07T02:37:16.337-0400: 71151.369: [PhantomReference, 0
> refs, 0.0000030 secs]2016-10-07T02:37:16.337-0400: 71151.369: [JNI
> Weak Reference, 0.0000080 secs] 1568M->915M(5120M), 2.6880870 secs]
>
> [Eden: 2048.0K(1384.0M)->0.0B(2112.0M) Survivors: 104.0M->0.0B
> Heap: 1568.8M(5120.0M)->915.2M(5120.0M)]
>
> Heap after GC invocations=55430 (full 5):
>
> garbage-first heap total 5242880K, used 937168K
> [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)
>
> region size 2048K, 0 young (0K), 0 survivors (0K)
>
> compacting perm gen total 96256K, used 94313K
> [0x00000007e0000000, 0x00000007e5e00000, 0x0000000800000000)
>
> the space 96256K, 97% used [0x00000007e0000000,
> 0x00000007e5c1a700, 0x00000007e5c1a800, 0x00000007e5e00000)
>
> No shared spaces configured.
>
> Could you please help me in giving your views on the following queries
>
> 1) Humongus allocation request for 72 mb failed, from the logs we
> can also see we have free space of around 3 GB. Does this means ,
> our application is encountering high amount of fragmentation ?.
>
> 2) Does tunning the gc params to make sure Mixed GC happens more ,
> will help in resolving such Full GC’s ?
>
> 3) Is there –XX:Print* flag which can tell us how many old gen and
> humongous regions we have (other than looking at [G1 Ergonomics]
> output , which sometimes gives old gen region count) ?
>
> Please do let me know , if you need any more information.
> Appreciate your help.
>
> Thanks and 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
> <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
> <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
> <http://www.blackrock.com/corporate/en-us/about-us/contacts-locations>.
>
> © 2016 BlackRock, Inc. All rights reserved.
>
>
>
> --
> Sent from my phone
>
>
> _______________________________________________
> 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/20161007/51190db5/attachment-0001.html>
More information about the hotspot-gc-use
mailing list