Why is G1 Full GC being triggered seeminly unnecessarily?

java garbage-collection g1gc
Martin picture Martin · Jan 15, 2013 · Viewed 8.1k times · Source

I am using

java version "1.7.0_09"
Java(TM) SE Runtime Environment (build 1.7.0_09-b05)
Java HotSpot(TM) 64-Bit Server VM (build 23.5-b02, mixed mode)

with G1 garbage collector. JVM argumens are

-server -Xss4096k -XX:MaxPermSize=512m -XX:PermSize=512m -Xms30G 
-Xmx30G -Xnoclassgc -XX:+UseNUMA -XX:+UseFastAccessorMethods 
-XX:ReservedCodeCacheSize=48m -XX:+UseStringCache 
-XX:+UseGCOverheadLimit -Duser.timezone=EET 
-Xmaxf1 -XX:+UseCompressedOops -XX:+DisableExplicitGC 
-XX:+AggressiveOpts -XX:CMSInitiatingOccupancyFraction=70 
-XX:+ParallelRefProcEnabled -XX:+UseAdaptiveSizePolicy 
-XX:MaxGCPauseMillis=500 -XX:+UseG1GC 
-XX:InitiatingHeapOccupancyPercent=0 
-XX:GCPauseIntervalMillis=10000 -XX:+PrintGCDetails 
-XX:+PrintHeapAtGC -XX:+PrintGCDateStamps -Xloggc:gc.log

However, I am experiencing following Full GC scans without any apparent reason, how to get rid of them?

GC log with some tail from preceding events:

{Heap before GC invocations=206 (full 8):
 garbage-first heap   total 31457280K, used 18323299K [0x00007fc6eb800000, 0x00007fce6b800000, 0x00007fce6b800000)
  region size 8192K, 768 young (6291456K), 31 survivors (253952K)
 compacting perm gen  total 524288K, used 145771K [0x00007fce6b800000, 0x00007fce8b800000, 0x00007fce8b800000)
   the space 524288K,  27% used [0x00007fce6b800000, 0x00007fce7465af18, 0x00007fce7465b000, 0x00007fce8b800000)
No shared spaces configured.
2013-01-16T11:45:31.290+0200: 20430.451: [GC pause (young), 0.54738500 secs]
   [Parallel Time: 510.7 ms]
      [GC Worker Start (ms):  20430451.7  20430451.8  20430451.8  20430451.8
       Avg: 20430451.8, Min: 20430451.7, Max: 20430451.8, Diff:   0.1]
      [Ext Root Scanning (ms):  22.3  68.3  21.8  20.8
       Avg:  33.3, Min:  20.8, Max:  68.3, Diff:  47.5]
      [Update RS (ms):  21.6  0.0  23.6  23.7
       Avg:  17.3, Min:   0.0, Max:  23.7, Diff:  23.7]
         [Processed Buffers : 77 0 18 55
          Sum: 150, Avg: 37, Min: 0, Max: 77, Diff: 77]
      [Scan RS (ms):  19.6  0.1  19.3  19.6
       Avg:  14.7, Min:   0.1, Max:  19.6, Diff:  19.5]
      [Object Copy (ms):  439.1  434.2  437.8  438.4
       Avg: 437.4, Min: 434.2, Max: 439.1, Diff:   4.9]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 1 1 1 1
          Sum: 4, Avg: 1, Min: 1, Max: 1, Diff: 0]
      [GC Worker End (ms):  20430954.5  20430954.6  20430954.5  20430954.4
       Avg: 20430954.5, Min: 20430954.4, Max: 20430954.6, Diff:   0.1]
      [GC Worker (ms):  502.7  502.8  502.7  502.6
       Avg: 502.7, Min: 502.6, Max: 502.8, Diff:   0.2]
      [GC Worker Other (ms):  8.0  8.0  8.0  8.1
       Avg:   8.0, Min:   8.0, Max:   8.1, Diff:   0.1]
   [Clear CT:   2.6 ms]
   [Other:  34.1 ms]
      [Choose CSet:   0.1 ms]
      [Ref Proc:  27.4 ms]
      [Ref Enq:   0.2 ms]
      [Free CSet:   5.4 ms]
   [Eden: 5896M(5896M)->0B(5688M) Survivors: 248M->456M Heap: 17893M(30720M)->12208M(30720M)]
 [Times: user=2.12 sys=0.02, real=0.55 secs]
Heap after GC invocations=207 (full 8):
 garbage-first heap   total 31457280K, used 12501684K [0x00007fc6eb800000, 0x00007fce6b800000, 0x00007fce6b800000)
  region size 8192K, 57 young (466944K), 57 survivors (466944K)
 compacting perm gen  total 524288K, used 145771K [0x00007fce6b800000, 0x00007fce8b800000, 0x00007fce8b800000)
   the space 524288K,  27% used [0x00007fce6b800000, 0x00007fce7465af18, 0x00007fce7465b000, 0x00007fce8b800000)
No shared spaces configured.
}
{Heap before GC invocations=207 (full 8):
 garbage-first heap   total 31457280K, used 19058524K [0x00007fc6eb800000, 0x00007fce6b800000, 0x00007fce6b800000)
  region size 8192K, 727 young (5955584K), 57 survivors (466944K)
 compacting perm gen  total 524288K, used 145775K [0x00007fce6b800000, 0x00007fce8b800000, 0x00007fce8b800000)
   the space 524288K,  27% used [0x00007fce6b800000, 0x00007fce7465bdd8, 0x00007fce7465be00, 0x00007fce8b800000)
No shared spaces configured.
2013-01-16T11:46:26.619+0200: 20485.781: [GC pause (mixed), 1.42356500 secs]
   [Parallel Time: 1385.9 ms]
      [GC Worker Start (ms):  20485786.6  20485786.6  20485786.6  20485786.7
       Avg: 20485786.6, Min: 20485786.6, Max: 20485786.7, Diff:   0.1]
      [Ext Root Scanning (ms):  22.1  70.0  22.2  21.3
       Avg:  33.9, Min:  21.3, Max:  70.0, Diff:  48.7]
      [Update RS (ms):  9.9  0.0  10.9  11.2
       Avg:   8.0, Min:   0.0, Max:  11.2, Diff:  11.2]
         [Processed Buffers : 13 0 25 17
          Sum: 55, Avg: 13, Min: 0, Max: 25, Diff: 25]
      [Scan RS (ms):  324.6  276.4  324.6  324.6
       Avg: 312.5, Min: 276.4, Max: 324.6, Diff:  48.2]
      [Object Copy (ms):  1021.1  1031.2  1019.8  1020.5
       Avg: 1023.1, Min: 1019.8, Max: 1031.2, Diff:  11.4]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0, Diff:   0.0]
         [Termination Attempts : 6 5 5 1
          Sum: 17, Avg: 4, Min: 1, Max: 6, Diff: 5]
      [GC Worker End (ms):  20487164.3  20487164.3  20487164.3  20487164.3
       Avg: 20487164.3, Min: 20487164.3, Max: 20487164.3, Diff:   0.0]
      [GC Worker (ms):  1377.7  1377.6  1377.6  1377.6
       Avg: 1377.7, Min: 1377.6, Max: 1377.7, Diff:   0.1]
      [GC Worker Other (ms):  8.2  8.3  8.3  8.3
       Avg:   8.3, Min:   8.2, Max:   8.3, Diff:   0.1]
   [Clear CT:   4.4 ms]
   [Other:  33.3 ms]
      [Choose CSet:   5.5 ms]
      [Ref Proc:   5.0 ms]
      [Ref Enq:   0.2 ms]
      [Free CSet:   9.1 ms]
   [Eden: 5360M(5688M)->0B(5784M) Survivors: 456M->360M Heap: 18616M(30720M)->11359M(30720M)]
 [Times: user=5.56 sys=0.01, real=1.42 secs]
Heap after GC invocations=208 (full 8):
 garbage-first heap   total 31457280K, used 11632594K [0x00007fc6eb800000, 0x00007fce6b800000, 0x00007fce6b800000)
  region size 8192K, 45 young (368640K), 45 survivors (368640K)
 compacting perm gen  total 524288K, used 145775K [0x00007fce6b800000, 0x00007fce8b800000, 0x00007fce8b800000)
   the space 524288K,  27% used [0x00007fce6b800000, 0x00007fce7465bdd8, 0x00007fce7465be00, 0x00007fce8b800000)
No shared spaces configured.
}
{Heap before GC invocations=208 (full 8):
 garbage-first heap   total 31457280K, used 11632594K [0x00007fc6eb800000, 0x00007fce6b800000, 0x00007fce6b800000)
  region size 8192K, 45 young (368640K), 45 survivors (368640K)
 compacting perm gen  total 524288K, used 145775K [0x00007fce6b800000, 0x00007fce8b800000, 0x00007fce8b800000)
   the space 524288K,  27% used [0x00007fce6b800000, 0x00007fce7465bdd8, 0x00007fce7465be00, 0x00007fce8b800000)
No shared spaces configured.
2013-01-16T11:46:28.060+0200: 20487.222: [Full GC 11359M->8807M(30720M), 32.4879420 secs]
 [Times: user=45.41 sys=0.21, real=32.48 secs]
Heap after GC invocations=209 (full 9):
 garbage-first heap   total 31457280K, used 9019206K [0x00007fc6eb800000, 0x00007fce6b800000, 0x00007fce6b800000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 524288K, used 145775K [0x00007fce6b800000, 0x00007fce8b800000, 0x00007fce8b800000)
   the space 524288K,  27% used [0x00007fce6b800000, 0x00007fce7465bdd8, 0x00007fce7465be00, 0x00007fce8b800000)
No shared spaces configured.
}

Other similar ones:

{Heap before GC invocations=105 (full 4):
 garbage-first heap   total 31457280K, used 12638024K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 56 young (458752K), 56 survivors (458752K)
 compacting perm gen  total 524288K, used 147352K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  28% used [0x00007fd2a2800000, 0x00007fd2ab7e61f8, 0x00007fd2ab7e6200, 0x00007fd2c2800000)
No shared spaces configured.
2013-01-14T10:31:31.240+0200: 14185.812: [Full GC 12341M->7092M(30720M), 25.3417840 secs]
 [Times: user=35.12 sys=0.21, real=25.33 secs]
Heap after GC invocations=106 (full 5):
 garbage-first heap   total 31457280K, used 7262578K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 524288K, used 147352K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  28% used [0x00007fd2a2800000, 0x00007fd2ab7e61f8, 0x00007fd2ab7e6200, 0x00007fd2c2800000)
No shared spaces configured.
}

{Heap before GC invocations=248 (full 11):
 garbage-first heap   total 31457280K, used 12262418K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 37 young (303104K), 37 survivors (303104K)
 compacting perm gen  total 524288K, used 152608K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2abd082e8, 0x00007fd2abd08400, 0x00007fd2c2800000)
No shared spaces configured.
2013-01-14T13:01:39.869+0200: 23194.441: [Full GC 11975M->7331M(30720M), 28.6147390 secs]
 [Times: user=40.31 sys=0.03, real=28.62 secs]
Heap after GC invocations=249 (full 12):
 garbage-first heap   total 31457280K, used 7507920K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 524288K, used 152608K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2abd082e8, 0x00007fd2abd08400, 0x00007fd2c2800000)
No shared spaces configured.
}

{Heap before GC invocations=399 (full 19):
 garbage-first heap   total 31457280K, used 13016093K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 54 young (442368K), 54 survivors (442368K)
 compacting perm gen  total 524288K, used 155475K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2abfd4c70, 0x00007fd2abfd4e00, 0x00007fd2c2800000)
No shared spaces configured.
2013-01-14T15:31:36.484+0200: 32191.056: [Full GC 12711M->7543M(30720M), 29.5013210 secs]
 [Times: user=41.39 sys=0.06, real=29.50 secs]
Heap after GC invocations=400 (full 20):
 garbage-first heap   total 31457280K, used 7724994K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 524288K, used 155475K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2abfd4c70, 0x00007fd2abfd4e00, 0x00007fd2c2800000)
No shared spaces configured.
}

{Heap before GC invocations=476 (full 26):
 garbage-first heap   total 31457280K, used 14622246K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 27 young (221184K), 27 survivors (221184K)
 compacting perm gen  total 524288K, used 156716K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2ac10b2b0, 0x00007fd2ac10b400, 0x00007fd2c2800000)
No shared spaces configured.
2013-01-14T18:46:41.545+0200: 43896.117: [Full GC 14279M->8107M(30720M), 31.6936770 secs]
 [Times: user=44.40 sys=0.18, real=31.69 secs]
Heap after GC invocations=477 (full 27):
 garbage-first heap   total 31457280K, used 8302054K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 524288K, used 156551K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2ac0e1fa0, 0x00007fd2ac0e2000, 0x00007fd2c2800000)
No shared spaces configured.
}

{Heap before GC invocations=522 (full 34):
 garbage-first heap   total 31457280K, used 16096219K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 30 young (245760K), 30 survivors (245760K)
 compacting perm gen  total 524288K, used 156869K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2ac1315d8, 0x00007fd2ac131600, 0x00007fd2c2800000)
No shared spaces configured.
2013-01-14T22:31:40.711+0200: 57395.283: [Full GC 15718M->11933M(30720M), 42.0857250 secs]
 [Times: user=60.13 sys=0.07, real=42.08 secs]
Heap after GC invocations=523 (full 35):
 garbage-first heap   total 31457280K, used 12219927K [0x00007fcb22800000, 0x00007fd2a2800000, 0x00007fd2a2800000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 524288K, used 156869K [0x00007fd2a2800000, 0x00007fd2c2800000, 0x00007fd2c2800000)
   the space 524288K,  29% used [0x00007fd2a2800000, 0x00007fd2ac1315d8, 0x00007fd2ac131600, 0x00007fd2c2800000)
No shared spaces configured.
}

Other similar issue reports:

http://grokbase.com/t/openjdk/hotspot-gc-use/1192sy84j5/g1c-strange-full-gc-behavior http://grokbase.com/p/openjdk/hotspot-gc-use/123ydf9c92/puzzling-why-is-a-full-gc-triggered-here http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2013-February/001484.html

I have been analyzing the issue using appdynamics profiler and I have found out that every time Full GC occurs, Code Cache (configured to its maximum) is full. It seems like a bug in GC.

See also the profiler image, two unnecessary Full GC:s in middle between 24/5 and 25/5. More importantly, they kill the server usability, because they last 60 seconds each:

Profiler log image http://eisler.vps.kotisivut.com/logs/g1gc-code-cache-full-gc-bug-illustration.png

See also discussion about Azul's pauseless GC, they seem to have worked out this kind of issues http://www.artima.com/lejava/articles/azul_pauseless_gc.html

Answer

emkays picture emkays · Feb 20, 2013

please see my reply in G1GC long pause with initial-mark

your every setting should has a solid reason to be here...and unfortunately some of them don't have e.g. -XX:+UseBiasedLocking (used for combination of tenured and young generation GCs, but G1GC is capable to handle both) -XX:+DisableExplicitGC (its unpredictable, in my experience its never restrict explicit gc calls)

please use/tweak accordingly below mentioned settings to get optimum results, I'm giving you baseline to move forward, hope so these settings will work for you: Java G1 garbage collection in production

Related questions

Java 7 (JDK 7) garbage collection and documentation on G1

Java 7 has been out for a while now, but I cannot find any good resources on the configuration of the garbage collectors, specifically the new G1 collector. My questions: Is G1 the default collector in Java 7 and if not how …

Read More
UseConcMarkSweepGC vs UseParallelGC

I'm currently having problems with very long garbage collection times. please see the followig. My current setup is that I'm using a -Xms1g and -Xmx3g. my application is using java 1.4.2. I don't have any garbage collection flags set. …

Read More
Java G1 garbage collection in production

Since Java 7 is going to use the new G1 garbage collection by default is Java going to be able to handle an order of magnitude larger heap without supposed "devastating" GC pause times? Has anybody actually implemented G1 in production, …

Read More