I'm tuning G1GC avoiding to occur FullGC. By following this tips http://www.infoq.com/articles/tuning-tips-G1-GC , I don't see any logs like "to-space exhausted".
Java HotSpot(TM) 64-Bit Server VM (24.76-b04) for linux-amd64 JRE (1.7.0_76-b13), built on Dec 18 2014 16:58:39 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 32934888k(13890072k free), swap 48197628k(48197628k free)
CommandLine flags:
-XX:AutoBoxCacheMax=3000000 -XX:ConcGCThreads=4 -XX:+DisableExplicitGC -XX:G1ReservePercent=25 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=11811160064 -XX:MaxDirectMemorySize=1073741824 -XX:MaxGCPauseMillis=1000 -XX:MaxHeapSize=11811160064 -XX:-OmitStackTraceInFastThrow
-XX:ParallelGCThreads=8 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution -XX:+UseCompressedOops -XX:+UseG1GC
For what other reasons would the GC decide to perform a full collection? Or it still has evacuation failures but the log is not enabled?
70861.400: [GC pause (mixed)
Desired survivor size 37748736 bytes, new threshold 1 (max 15)
- age 1: 49450208 bytes, 49450208 total
- age 2: 3236616 bytes, 52686824 total
- age 3: 10086240 bytes, 62773064 total
- age 4: 188936 bytes, 62962000 total
- age 5: 816536 bytes, 63778536 total
- age 6: 1024560 bytes, 64803096 total
- age 7: 1341640 bytes, 66144736 total
- age 8: 1562648 bytes, 67707384 total
- age 9: 59200 bytes, 67766584 total
, 0.2471520 secs]
[Parallel Time: 225.0 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 70861401.2, Avg: 70861401.4, Max: 70861401.7, Diff: 0.6]
[Ext Root Scanning (ms): Min: 3.8, Avg: 4.1, Max: 4.5, Diff: 0.6, Sum: 33.0]
[Update RS (ms): Min: 93.2, Avg: 93.4, Max: 93.5, Diff: 0.3, Sum: 746.9]
[Processed Buffers: Min: 92, Avg: 108.0, Max: 124, Diff: 32, Sum: 864]
[Scan RS (ms): Min: 29.7, Avg: 29.7, Max: 29.8, Diff: 0.1, Sum: 238.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 95.9, Avg: 96.2, Max: 97.0, Diff: 1.1, Sum: 769.6]
[Termination (ms): Min: 0.0, Avg: 0.8, Max: 1.0, Diff: 1.0, Sum: 6.4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 0.7]
[GC Worker Total (ms): Min: 224.1, Avg: 224.3, Max: 224.6, Diff: 0.6, Sum: 1794.6]
[GC Worker End (ms): Min: 70861625.7, Avg: 70861625.7, Max: 70861625.9, Diff: 0.2]
[Code Root Fixup: 0.2 ms]
[Code Root Migration: 0.1 ms]
[Clear CT: 4.8 ms]
[Other: 17.2 ms]
[Choose CSet: 0.4 ms]
[Ref Proc: 7.5 ms]
[Ref Enq: 0.1 ms]
[Free CSet: 1.0 ms]
[Eden: 488.0M(488.0M)->0.0B(2956.0M) Survivors: 72.0M->20.0M Heap: 5882.4M(11.0G)->5394.1M(11.0G)]
71319.172: [GC pause (young) (initial-mark)
Desired survivor size 195035136 bytes, new threshold 15 (max 15)
- age 1: 3965480 bytes, 3965480 total
, 0.2243330 secs]
[Parallel Time: 182.7 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 71319173.4, Avg: 71319173.6, Max: 71319174.0, Diff: 0.6]
[Ext Root Scanning (ms): Min: 3.4, Avg: 4.0, Max: 4.4, Diff: 1.0, Sum: 31.8]
[Code Root Marking (ms): Min: 2.0, Avg: 2.7, Max: 6.0, Diff: 4.0, Sum: 21.4]
[Update RS (ms): Min: 105.7, Avg: 109.2, Max: 110.6, Diff: 4.9, Sum: 873.2]
[Processed Buffers: Min: 115, Avg: 127.6, Max: 142, Diff: 27, Sum: 1021]
[Scan RS (ms): Min: 11.7, Avg: 12.6, Max: 12.9, Diff: 1.1, Sum: 100.9]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Object Copy (ms): Min: 52.2, Avg: 52.7, Max: 52.9, Diff: 0.7, Sum: 421.2]
[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.2, Max: 0.6, Diff: 0.6, Sum: 1.9]
[GC Worker Total (ms): Min: 181.0, Avg: 181.3, Max: 181.6, Diff: 0.6, Sum: 1450.7]
[GC Worker End (ms): Min: 71319354.8, Avg: 71319355.0, Max: 71319355.3, Diff: 0.6]
[Code Root Fixup: 0.3 ms]
[Code Root Migration: 0.2 ms]
[Clear CT: 3.6 ms]
[Other: 37.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 29.8 ms]
[Ref Enq: 0.5 ms]
[Free CSet: 2.3 ms]
[Eden: 2332.0M(2956.0M)->0.0B(2872.0M) Survivors: 20.0M->72.0M Heap: 7725.6M(11.0G)->5448.0M(11.0G)]
[Times: user=1.51 sys=0.00, real=0.22 secs]
71319.397: [GC concurrent-root-region-scan-start]
71319.468: [GC concurrent-root-region-scan-end, 0.0707700 secs]
71319.468: [GC concurrent-mark-start]
71320.512: [GC pause (young)
Desired survivor size 192937984 bytes, new threshold 15 (max 15)
- age 1: 57002072 bytes, 57002072 total
- age 2: 3685360 bytes, 60687432 total
, 0.1300980 secs]
[Parallel Time: 122.5 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 71320513.1, Avg: 71320513.3, Max: 71320513.8, Diff: 0.7]
[Ext Root Scanning (ms): Min: 3.5, Avg: 4.0, Max: 4.3, Diff: 0.8, Sum: 32.4]
[SATB Filtering (ms): Min: 0.0, Avg: 0.1, Max: 0.8, Diff: 0.8, Sum: 0.8]
[Update RS (ms): Min: 75.2, Avg: 75.7, Max: 76.0, Diff: 0.8, Sum: 605.8]
[Processed Buffers: Min: 169, Avg: 183.8, Max: 202, Diff: 33, Sum: 1470]
[Scan RS (ms): Min: 2.9, Avg: 2.9, Max: 3.0, Diff: 0.1, Sum: 23.3]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 38.7, Avg: 38.8, Max: 38.9, Diff: 0.1, Sum: 310.4]
[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.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
[GC Worker Total (ms): Min: 121.2, Avg: 121.7, Max: 121.9, Diff: 0.7, Sum: 973.3]
[GC Worker End (ms): Min: 71320635.0, Avg: 71320635.0, Max: 71320635.0, Diff: 0.0]
[Code Root Fixup: 0.2 ms]
[Code Root Migration: 0.0 ms]
[Clear CT: 1.4 ms]
[Other: 6.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.7 ms]
[Ref Enq: 0.0 ms]
[Free CSet: 0.5 ms]
[Eden: 260.0M(2872.0M)->0.0B(2736.0M) Survivors: 72.0M->68.0M Heap: 5828.3M(11.0G)->5562.4M(11.0G)]
[Times: user=0.98 sys=0.00, real=0.12 secs]
71320.645: [Full GC 5562M->3567M(11G), 23.7159350 secs]
[Eden: 0.0B(2736.0M)->0.0B(4804.0M) Survivors: 68.0M->0.0B Heap: 5562.4M(11.0G)->3567.2M(11.0G)], [Perm: 34637K->34637K(36864K)]
[Times: user=38.34 sys=0.02, real=23.72 secs]
71344.362: [GC concurrent-mark-abort]
71436.544: [GC pause (young)
Desired survivor size 316669952 bytes, new threshold 15 (max 15)
- age 1: 448512 bytes, 448512 total
- age 2: 55511136 bytes, 55959648 total
- age 3: 3685280 bytes, 59644928 total
, 0.2012910 secs]
[Parallel Time: 183.5 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 71436545.9, Avg: 71436546.2, Max: 71436546.6, Diff: 0.7]
[Ext Root Scanning (ms): Min: 5.2, Avg: 5.4, Max: 5.9, Diff: 0.7, Sum: 43.3]
[Update RS (ms): Min: 44.0, Avg: 45.8, Max: 52.6, Diff: 8.6, Sum: 366.0]
[Processed Buffers: Min: 118, Avg: 128.2, Max: 136, Diff: 18, Sum: 1026]
[Scan RS (ms): Min: 5.2, Avg: 11.8, Max: 13.5, Diff: 8.3, Sum: 94.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Object Copy (ms): Min: 118.8, Avg: 118.9, Max: 119.1, Diff: 0.3, Sum: 951.4]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
[GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: 2.3]
[GC Worker Total (ms): Min: 181.9, Avg: 182.3, Max: 182.6, Diff: 0.7, Sum: 1458.3]
[GC Worker End (ms): Min: 71436728.2, Avg: 71436728.5, Max: 71436728.7, Diff: 0.5]
[Code Root Fixup: 0.2 ms]
[Code Root Migration: 0.3 ms]
[Clear CT: 4.2 ms]
[Other: 13.1 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 6.6 ms]
[Ref Enq: 0.1 ms]
[Free CSet: 3.6 ms]
[Eden: 4804.0M(4804.0M)->0.0B(3412.0M) Survivors: 0.0B->152.0M Heap: 9208.4M(11.0G)->4554.4M(11.0G)]
[Times: user=1.50 sys=0.00, real=0.20 secs]
It started a FullGC at 71320.645, but looks no evacuation failures happened, any ideas?
It's likely not a good idea to run G1GC on java 7. Back then it had a lot of problematic behaviors. Among them that class unloading needed a full GC, this has been fixed with jdk8u40
Not to mention that GC logs give more useful information in 8.
Other causes are thinkable too though, such as humongous object allocation needing more consecutive free regions than are available. 8's logs would probably prove more useful.
Edit: Actually, that feature might be in 7u45 behind a flag, try
-XX:+PrintGCCause