X

Poonam Bajaj's Blog

  • November 25, 2014

Increased heap usage with G1 GC

Poonam Parhar
Consulting Member of Technical Staff

G1 garbage collector is a predictable low pause collector that works efficiently to achieve the low pause time goals. To meet the set pause time goals, G1 tries to:

  • pick only those many old heap regions for the collection-set that it thinks could be collected in the specified goal time
  • adapt the young generation size to contain the collection times within the set goal.

In that effort, however, G1 may end up causing a side effect of increased usage of the Java Heap.

For example, in an experimental run with CMS using a heap size of 8GB, the maximum observed heap usage was around 4GB. But after switching to G1, with -XX:MaxGCPauseMillis=50, the heap usage went up to 6GB. In both the cases, the application load was same.

Part of the CMS GC logs:
------------------------
2014-11-21T05:18:18.790-0500: 1918944.850: [GC2014-11-21T05:18:18.790-0500: 1918944.850: [ParNew: 32704K->64K(32704K), 0.0698450 secs] 4274067K->4247066K(8388544K), 0.0700480 secs] [Times: user=0.32 sys=0.01, real=0.06 secs]
2014-11-21T05:18:18.864-0500: 1918944.924: [GC [1 CMS-initial-mark: 4247002K(8355840K)] 4247095K(8388544K), 0.1249300 secs] [Times: user=0.12 sys=0.00, real=0.13 secs]
2014-11-21T05:18:18.989-0500: 1918945.050: [CMS-concurrent-mark-start]
2014-11-21T05:18:31.163-0500: 1918957.223: [GC2014-11-21T05:18:31.163-0500: 1918957.223: [ParNew: 32704K->64K(32704K), 0.0365220 secs] 4279706K->4247775K(8388544K), 0.0367530 secs] [Times: user=0.26 sys=0.00, real=0.04 secs]
2014-11-21T05:18:37.588-0500: 1918963.648: [CMS-concurrent-mark: 18.547/18.598 secs] [Times: user=39.03 sys=0.47, real=18.59 secs]
2014-11-21T05:18:37.588-0500: 1918963.648: [CMS-concurrent-preclean-start]
2014-11-21T05:18:37.708-0500: 1918963.768: [CMS-concurrent-preclean: 0.114/0.120 secs] [Times: user=0.13 sys=0.00, real=0.12 secs]
2014-11-21T05:18:37.708-0500: 1918963.768: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2014-11-21T05:18:42.724-0500: 1918968.785: [CMS-concurrent-abortable-preclean: 3.008/5.016 secs] [Times: user=3.34 sys=0.12, real=5.02 secs]
2014-11-21T05:18:42.728-0500: 1918968.789: [GC[YG occupancy: 25109 K (32704 K)]2014-11-21T05:18:42.728-0500: 1918968.789: [Rescan (parallel) , 0.1196710 secs]2014-11-21T05:18:42.848-0500: 1918968.909: [weak refs processing, 0.0002300 secs]2014-11-21T05:18:42.848-0500: 1918968.909: [class unloading, 0.0219670 secs]2014-11-21T05:18:42.870-0500: 1918968.931: [scrub symbol table, 0.0144900 secs]2014-11-21T05:18:42.885-0500: 1918968.945: [scrub string table, 0.0046370 secs] [1 CMS-remark: 4247711K(8355840K)] 4272821K(8388544K), 0.1740580 secs] [Times: user=0.99 sys=0.00, real=0.17 secs]
2014-11-21T05:18:42.903-0500: 1918968.963: [CMS-concurrent-sweep-start]

Part of the G1 GC logs:
-----------------------
  [Times: user=0.40 sys=0.01, real=0.06 secs]
    [Eden: 368.0M(368.0M)->0.0B(372.0M) Survivors: 40.0M->36.0M Heap: 6622.9M(8192.0M)->6259.7M(8192.0M)]
 2014-10-08T04:38:46.675-0400: 1311963.055: [GC pause (young) (initial-mark), 0.0564110 secs]
    [Parallel Time: 51.4 ms, GC Workers: 8]
       [GC Worker Start (ms): Min: 1311963055.7, Avg: 1311963055.7, Max: 1311963055.8, Diff: 0.1]
       [Ext Root Scanning (ms): Min: 6.3, Avg: 11.8, Max: 16.2, Diff: 9.9, Sum: 94.7]
       [Update RS (ms): Min: 3.0, Avg: 4.7, Max: 7.4, Diff: 4.4, Sum: 37.8]
          [Processed Buffers: Min: 2, Avg: 8.8, Max: 18, Diff: 16, Sum: 70]
       [Scan RS (ms): Min: 1.0, Avg: 1.3, Max: 1.4, Diff: 0.5, Sum: 10.0]
       [Object Copy (ms): Min: 29.0, Avg: 33.0, Max: 39.7, Diff: 10.7, Sum: 264.3]
       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]
       [GC Worker Total (ms): Min: 50.9, Avg: 51.0, Max: 51.1, Diff: 0.2, Sum: 407.8]
       [GC Worker End (ms): Min: 1311963106.7, Avg: 1311963106.7, Max: 1311963106.9, Diff: 0.2]
    [Code Root Fixup: 0.0 ms]
    [Clear CT: 1.5 ms]
    [Other: 3.6 ms]
       [Choose CSet: 0.0 ms]
       [Ref Proc: 1.8 ms]
       [Ref Enq: 0.1 ms]
       [Free CSet: 0.7 ms]
    [Eden: 372.0M(372.0M)->0.0B(368.0M) Survivors: 36.0M->40.0M Heap: 6631.7M(8192.0M)->6262.8M(8192.0M)]
  [Times: user=0.42 sys=0.01, real=0.05 secs]
    ......
    ......
 2014-10-08T04:34:59.344-0400: 1311735.724: [GC pause (mixed), 0.0666200 secs]
    [Parallel Time: 60.4 ms, GC Workers: 8]
       [GC Worker Start (ms): Min: 1311735724.4, Avg: 1311735724.5, Max: 1311735724.5, Diff: 0.2]
       [Ext Root Scanning (ms): Min: 10.1, Avg: 13.0, Max: 19.3, Diff: 9.2, Sum: 104.3]
       [Update RS (ms): Min: 0.0, Avg: 4.5, Max: 6.6, Diff: 6.6, Sum: 35.6]
          [Processed Buffers: Min: 0, Avg: 9.1, Max: 20, Diff: 20, Sum: 73]
       [Scan RS (ms): Min: 3.5, Avg: 4.8, Max: 5.1, Diff: 1.6, Sum: 38.7]
       [Object Copy (ms): Min: 37.1, Avg: 37.6, Max: 38.4, Diff: 1.3, Sum: 301.1]
       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
       [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
       [GC Worker Total (ms): Min: 60.0, Avg: 60.1, Max: 60.2, Diff: 0.2, Sum: 481.1]
       [GC Worker End (ms): Min: 1311735784.5, Avg: 1311735784.6, Max: 1311735784.7, Diff: 0.2]
    [Code Root Fixup: 0.0 ms]
    [Clear CT: 2.2 ms]
    [Other: 4.0 ms]
       [Choose CSet: 0.1 ms]
       [Ref Proc: 1.9 ms]
       [Ref Enq: 0.0 ms]
       [Free CSet: 0.9 ms]
    [Eden: 372.0M(372.0M)->0.0B(368.0M) Survivors: 36.0M->40.0M Heap: 6633.2M(8192.0M)->6254.9M(8192.0M)]
------------------------------------------

The reason for this unexpected behaviour is that G1 tries to select minimal number of old regions in the collection-set so that it can do the evacuation pauses within the specified pause time goal. Due to this, it fails to clean up the garbage in the old regions, and hence the increased heap usage.

To overcome this side effect with G1, if one does not have very strict pause time goals, the young generation size can be increased so that most of the die-young objects get collected in the young regions itself and don't get promoted to the old generation. One can also try relaxing the pause time goals so that G1 includes more number of old regions in the collection set and good amount of garbage gets collected with the evacuation pauses.


Join the discussion

Comments ( 1 )
  • guest Wednesday, March 16, 2016

    2016-03-15T14:59:34.082+0100: 74908.030: [GC pause (G1 Evacuation Pause) (young)/(mixed) (initial-mark), 0.3472642 secs]

    [Parallel Time: 101.1 ms, GC Workers: 2]

    [GC Worker Start (ms): Min: 74908031.9, Avg: 74908031.9, Max: 74908031.9, Diff: 0.0]

    [Ext Root Scanning (ms): Min: 16.8, Avg: 17.0, Max: 17.2, Diff: 0.3, Sum: 34.0]

    [Update RS (ms): Min: 17.5, Avg: 17.7, Max: 18.0, Diff: 0.5, Sum: 35.5]

    [Processed Buffers: Min: 48, Avg: 51.0, Max: 54, Diff: 6, Sum: 102]

    [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]

    [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

    [Object Copy (ms): Min: 64.4, Avg: 64.7, Max: 65.1, Diff: 0.7, Sum: 129.5]

    [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.0, Sum: 0.1]

    [GC Worker Total (ms): Min: 99.6, Avg: 99.6, Max: 99.6, Diff: 0.0, Sum: 199.2]

    [GC Worker End (ms): Min: 74908131.5, Avg: 74908131.5, Max: 74908131.5, Diff: 0.0]

    [Code Root Fixup: 0.9 ms]

    [Code Root Purge: 0.0 ms]

    [Clear CT: 0.2 ms]

    [Other: 245.1 ms]

    [Choose CSet: 0.0 ms]

    [Ref Proc: 124.3 ms]

    [Ref Enq: 0.1 ms]

    [Redirty Cards: 0.2 ms]

    [Humongous Reclaim: 0.0 ms]

    [Free CSet: 0.4 ms]

    [Eden: 238.0M(238.0M)->0.0B(230.0M) Survivors: 18.0M->26.0M Heap: 3169.0M(5120.0M)->2939.0M(5120.0M)]

    [Times: user=0.43 sys=0.00, real=0.35 secs]

    I am getting this very frequently, What does it mean?

    How can i resolve this issue?


Please enter your name.Please provide a valid email address.Please enter a comment.CAPTCHA challenge response provided was incorrect. Please try again.