G1 root cause and tuning

Fri Mar 27 15:30:30 UTC 2015

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=-serverwrapper.java.additional.2=-XX:+PrintCommandLineFlagswrapper.java.additional.3=-XX:+UseG1GC
wrapper.java.additional.7=-XX:MaxGCPauseMillis=2500
wrapper.java.additional.8=-Dsun.rmi.dgc.client.gcInterval=0x7ffffffffffffffewrapper.java.additional.9=-Dsun.rmi.dgc.server.gcInterval=0x7ffffffffffffffewrapper.java.additional.10=-XX:+HeapDumpOnOutOfMemoryErrorwrapper.java.additional.11=-verbose:gcwrapper.java.additional.12=-XX:+PrintGCDetailswrapper.java.additional.13=-Ducmdb.home=%SERVER_BASE_DIR%
wrapper.java.additional.52=-XX:+PrintGCTimeStampswrapper.java.additional.53=-XX:+PrintGCApplicationStoppedTimewrapper.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 secondsINFO   | 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 GCERROR  | 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150327/407c0191/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: logs.zip
Type: application/octet-stream
Size: 1295341 bytes
Desc: not available
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20150327/407c0191/logs-0001.zip>