G1 Full GC without to-space exhausted

Mon Jan 6 15:31:55 PST 2014

Hi All

We have some interesting G1 GC logs and want to share with you. G1 triggers
full GC without to-space exhausted.

G1 parameters we use:
 -server -XX:MaxGCPauseMillis=100 -XX:G1HeapRegionSize=32m
-XX:InitiatingHeapOccupancyPercent=65 -XX:G1ReservePercent=20
-XX:G1HeapWastePercent=5 -XX:G1MixedGCLiveThresholdPercent=75
-XX:G1RSetRegionEntries=4096

Note:
    1. This machine do not have any full GCs after applying
"*-XX:G1ReservePercent=20
-XX:G1HeapWastePercent=5 -XX:G1MixedGCLiveThresholdPercent=75*" since Dec
26, 2013
    2. Yesterday, we set -XX:G1RSetRegionEntries=4096 to reduce RSet
coarsening and we've observed following two full GCs after a few hours (~
20 hours).
    3. Another production machine with similar traffic (without
-XX:G1RSetRegionEntries=4096) do not have full GCs so far (since Dec 26,
2013)

*First Full GC*2014-01-06T17:21:11.644-0500: 72496.707: [GC pause (young)
Desired survivor size 234881024 bytes, new threshold 3 (max 15)
- age   1:   91549360 bytes,   91549360 total
- age   2:   83989936 bytes,  175539296 total
- age   3:   80986496 bytes,  256525792 total
 72496.708: [G1Ergonomics (CSet Construction) start choosing CSet,
_pending_cards: 29358, predicted base time: 43.17 ms, remaining time: 56.83
ms, target pause time: 100.0\
0 ms]
 72496.708: [G1Ergonomics (CSet Construction) add young regions to CSet,
eden: 91 regions, survivors: 14 regions, predicted young region time: 34.53
ms]
 72496.708: [G1Ergonomics (CSet Construction) finish choosing CSet, eden:
91 regions, survivors: 14 regions, old: 0 regions, predicted pause time:
77.70 ms, target pause t\
ime: 100.00 ms]
 72496.786: [G1Ergonomics (Concurrent Cycles) request concurrent cycle
initiation, reason: occupancy higher than threshold, occupancy: 56841207808
bytes, allocation reques\
t: 0 bytes, threshold: 46172576125 bytes (65.00 %), source: end of GC]
, 0.0788860 secs]
   [Parallel Time: 56.7 ms, GC Workers: 18]
      [GC Worker Start (ms): Min: 72496707.9, Avg: 72496708.1, Max:
72496708.3, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 3.1, Avg: 3.6, Max: 5.2, Diff: 2.0,
Sum: 64.6]
      [Update RS (ms): Min: 8.9, Avg: 10.2, Max: 13.1, Diff: 4.3, Sum:
183.5]
         [Processed Buffers: Min: 5, Avg: 19.4, Max: 26, Diff: 21, Sum: 349]
      [Scan RS (ms): Min: 3.9, Avg: 6.8, Max: 7.2, Diff: 3.3, Sum: 121.7]
      [Object Copy (ms): Min: 35.2, Avg: 35.3, Max: 35.4, Diff: 0.2, Sum:
635.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum:
0.9]
      [GC Worker Total (ms): Min: 55.7, Avg: 55.9, Max: 56.1, Diff: 0.4,
Sum: 1006.2]
      [GC Worker End (ms): Min: 72496764.0, Avg: 72496764.0, Max:
72496764.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 9.7 ms]
   [Other: 12.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 6.5 ms]
      [Ref Enq: 1.3 ms]
      [Free CSet: 0.6 ms]
   [Eden: 2912.0M(2912.0M)->0.0B(2944.0M) Survivors: 448.0M->416.0M Heap:
55.9G(66.2G)->53.3G(66.2G)]
 [Times: user=1.14 sys=0.01, real=0.07 secs]
*2014-01-06T17:21:17.773-0500: 72502.837: [Full GC 55G->44G(66G),
42.9123930 secs]*
   [Eden: 1856.0M(2944.0M)->0.0B(8224.0M) Survivors: 416.0M->0.0B Heap:
55.1G(66.2G)->44.2G(66.2G)]
 [Times: user=89.27 sys=0.32, real=42.91 secs]

*Second Full GC*

2014-01-06T17:22:19.756-0500: 72564.819: [GC pause (young)
Desired survivor size 234881024 bytes, new threshold 1 (max 15)
- age   1:  480804360 bytes,  480804360 total
 72564.819: [G1Ergonomics (CSet Construction) start choosing CSet,
_pending_cards: 20485, predicted base time: 39.00 ms, remaining time: 61.00
ms, target pause time: 100.0\
0 ms]
 72564.819: [G1Ergonomics (CSet Construction) add young regions to CSet,
eden: 91 regions, survivors: 14 regions, predicted young region time: 58.68
ms]
 72564.820: [G1Ergonomics (CSet Construction) finish choosing CSet, eden:
91 regions, survivors: 14 regions, old: 0 regions, predicted pause time:
97.68 ms, target pause t\
ime: 100.00 ms]
 72564.921: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason:
recent GC overhead higher than threshold after GC, recent GC overhead:
35.26 %, threshold: 10.00 %,\
 uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
, 0.1015370 secs]
   [Parallel Time: 86.3 ms, GC Workers: 18]
      [GC Worker Start (ms): Min: 72564819.8, Avg: 72564820.0, Max:
72564820.1, Diff: 0.3]
      [Ext Root Scanning (ms): Min: 3.1, Avg: 3.7, Max: 5.4, Diff: 2.2,
Sum: 65.8]
      [SATB Filtering (ms): Min: 0.0, Avg: 0.2, Max: 4.3, Diff: 4.3, Sum:
4.3]
      [Update RS (ms): Min: 1.0, Avg: 8.7, Max: 69.5, Diff: 68.5, Sum:
156.8]
         [Processed Buffers: Min: 4, Avg: 18.6, Max: 24, Diff: 20, Sum: 335]
      [Scan RS (ms): Min: 0.0, Avg: 1.4, Max: 1.8, Diff: 1.8, Sum: 25.6]
      [Object Copy (ms): Min: 12.4, Avg: 71.3, Max: 75.2, Diff: 62.9, Sum:
1284.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 2.2]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum:
0.6]
      [GC Worker Total (ms): Min: 85.4, Avg: 85.5, Max: 85.7, Diff: 0.3,
Sum: 1539.3]
      [GC Worker End (ms): Min: 72564905.5, Avg: 72564905.5, Max:
72564905.6, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 5.8 ms]
   [Other: 9.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 5.7 ms]
      [Ref Enq: 1.5 ms]
      [Free CSet: 0.4 ms]
   [Eden: 2912.0M(2912.0M)->0.0B(2912.0M) Survivors: 448.0M->448.0M Heap:
48.4G(66.2G)->46.1G(66.2G)]
 [Times: user=1.62 sys=0.04, real=0.10 secs]
*2014-01-06T17:22:21.027-0500: 72566.090: [Full GC 47G->42G(66G),
39.4019900 secs]*
   [Eden: 1344.0M(2912.0M)->0.0B(4640.0M) Survivors: 448.0M->0.0B Heap:
47.4G(66.2G)->42.1G(66.2G)]
 [Times: user=85.26 sys=0.25, real=39.39 secs]

*RSet Summarize*

 Concurrent RS processed -1783517237 cards
  Of 13181224 completed buffers:
     13012752 ( 98.7%) by conc RS threads.
       168472 (  1.3%) by mutator threads.
  Conc RS threads times(s)
          0.00     0.00     0.00     0.00     0.00     0.00     0.00
0.00     0.00     0.00     0.00     0.00     0.00     0.00     0.00
0.00     0.00     0.00     0.00
  Total heap region rem set sizes = 7388596K.  Max = 11538K.
  Static structures = 347K, free_lists = 27631K.
    123115917 occupied cards represented.
    Max size region =
84:(O)[0x00007fcb36000000,0x00007fcb37ffe258,0x00007fcb38000000], size =
11539K, occupied = 1472K.
    Did 0 coarsenings.

Thanks
Shengzhe
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140106/95ee6d50/attachment-0001.html 