G1 root cause and tuning

[Yu Zhang]

Medan,

I could not find the humongous allocation in the logs you attached.  But 
from the snip you provided, it seems the humongous objects allocation 
(the bigger one is ~10g) might be the issue.
If you can provide a cleaner gc log( with -Xloggc:gc.log) without the 
wrapper information, it would be easier to analyze.

Thanks,
Jenny

On 3/27/2015 8:30 AM, Medan Gavril wrote:
> Hi ,
>
> I saw your G1 presentation and I found it good and interesting. I am 
> new to G1 tuning and I would need you suggestions if you  have time.
>
> In our app, when we have a FULL GC :
>     1. it restarts the application
>     2. we cannot get the right data to understand the root cause
>
> We switched from CMS to G1 in order to avoid long FULL GCs.
>
> JRE 1.17 update 17 it is being used.
>
> GC params:
>
> wrapper.java.additional.1=-server
> wrapper.java.additional.2=-XX:+PrintCommandLineFlags
> wrapper.java.additional.3=-XX:+UseG1GC
> wrapper.java.additional.7=-XX:MaxGCPauseMillis=2500
> wrapper.java.additional.8=-Dsun.rmi.dgc.client.gcInterval=0x7ffffffffffffffe
> wrapper.java.additional.9=-Dsun.rmi.dgc.server.gcInterval=0x7ffffffffffffffe
> wrapper.java.additional.10=-XX:+HeapDumpOnOutOfMemoryError
> wrapper.java.additional.11=-verbose:gc
> wrapper.java.additional.12=-XX:+PrintGCDetails
> wrapper.java.additional.13=-Ducmdb.home=%SERVER_BASE_DIR%
>
> wrapper.java.additional.52=-XX:+PrintGCTimeStamps
> wrapper.java.additional.53=-XX:+PrintGCApplicationStoppedTime
> wrapper.java.additional.55=-XX:+PrintAdaptiveSizePolicy
>
> The error from wrapper log is:
>
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |    [Eden: 
> 692M(968M)->0B(972M) Survivors: 56M->52M Heap: 
> 8127M(22480M)->7436M(22480M)]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  [Times: user=1.51 
> sys=0.02, real=0.19 secs] /
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.265: 
> [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: humongous 
> allocation request failed, allocation request: 189267984 bytes]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.265: 
> [G1Ergonomics (Heap Sizing) expand the heap, requested expansion 
> amount: 188743680 bytes, attempted expansion amount: 188743680 bytes]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.265: 
> [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap 
> expansion operation failed]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 | Total time for which 
> application threads were stopped: 0.2031307 seconds/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.285: 
> [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: humongous 
> allocation request failed, allocation request: 189267984 bytes]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.285: 
> [G1Ergonomics (Heap Sizing) expand the heap, requested expansion 
> amount: 188743680 bytes, attempted expansion amount: 188743680 bytes]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.285: 
> [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap 
> expansion operation failed]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.285: 
> [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: allocation 
> request failed, allocation request: 189267984 bytes]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.285: 
> [G1Ergonomics (Heap Sizing) expand the heap, requested expansion 
> amount: 189267984 bytes, attempted expansion amount: 192937984 bytes]/
> /INFO   | jvm 1    | 2015/03/25 15:23:43.268 |  93238.285: 
> [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap 
> expansion operation failed]/
> */INFO   | jvm 1    | 2015/03/25 15:23:43.268 | 93238.285: [Full GC/*
> /ERROR  | wrapper  | 2015/03/25 15:25:57.694 | JVM appears hung: 
> *Timed out waiting for signal from JVM.*/
> /ERROR  | wrapper  | 2015/03/25 15:25:58.021 | JVM did not exit /
>
>
> /INFO   | jvm 1    | 2015/03/25 15:14:41.289 |  92696.335: 
> [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, 
> reason: occupancy higher than threshold, occupancy: 10603200512 bytes, 
> allocation request: 14584896 bytes, threshold: 10607394780 bytes 
> (45.00 %), source: concurrent humongous allocation]/
> /INFO   | jvm 1    | 2015/03/25 15:14:41.289 |  92696.337: 
> [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, 
> reason: requested by GC cause, GC cause: G1 Humongous Allocation]/
> /INFO   | jvm 1    | 2015/03/25 15:14:41.289 |  92696.337: 
> [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: 
> concurrent cycle initiation requested]/
> /INFO   | jvm 1    | 2015/03/25 15:14:41.289 | 92696.337: [GC pause 
> (young) 92696.338: [G1Ergonomics (CSet Construction) start choosing 
> CSet, predicted base time: 165.76 ms, remaining time: 2334.24 ms, 
> target pause time: 2500.00 ms]/
> /INFO   | jvm 1    | 2015/03/25 15:14:41.289 |  92696.338: 
> [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 114 
> regions, survivors: 8 regions, predicted young region time: 32.04 ms]/
> /INFO   | jvm 1    | 2015/03/25 15:14:41.289 |  92696.338: 
> [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 114 
> regions, survivors: 8 regions, old: 0 regions, predicted pause time: 
> 197.80 ms, target pause time: 2500.00 ms]/
> /INFO   | jvm 1    | 2015/03/25 15:14:41.398 |  (initial-mark), 
> 0.15117107 secs]/
> /
> /
> /We increased the wrapper timeout but still no useful data about the 
> FULL GC./
> /
> /
> /Any suggestion is highly appreciated. Currently I suggested to add 
>  "PrintHeapAtGCExtended "/
> /
> /
> /Best Regards,
> Gabi Medan/
>
>
>
> _______________________________________________
> 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/20150327/bdb33c7c/attachment.html>