Warum wird G1 Full GC scheinbar unnötig ausgelöst?

Question

I

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) 

mit G1 Garbage Collector verwenden. JVM argumens sind

-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 

Allerdings erlebe ich folgende Voll GC-Scans ohne ersichtlichen Grund, wie man sie loswerden?

GC log mit einigen Schwanz aus vorangegangenen Veranstaltungen:

{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. 
} 

Andere ähnliche:

{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.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. 
} 

Andere ähnliche Ausgabe berichtet:

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

Ich habe das Problem mit appdynamics profiler analysiert und festgestellt, dass bei jedem Auftreten von Full GC Code Cache (maximal konfiguriert) voll ist. Es scheint wie ein Fehler in GC.

Siehe auch das Profilerbild, zwei unnötige Full GC: s in der Mitte zwischen 24/5 und 25/5. Noch wichtiger ist, töten sie die Usability-Server, weil sie 60 Sekunden dauern jeweils:

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

Siehe auch Diskussion über Azul pauseless GC, scheinen sie diese Art von Fragen ausgearbeitet haben http://www.artima.com/lejava/articles/azul_pauseless_gc.html

Answer 1

Wir nahmen diesen Fehler auf 1,7 ._u06 und vor ein paar Tagen auf 1.7.0_21-b11 aufgerüstet und wir haben seit dem Upgrade keine vollständigen GCs mehr gesehen, daher scheint dieser Bug in JVM behoben worden zu sein. Die Code-Cache-Speicherprofile sehen nun auch im Profiler viel schöner aus. In der Vergangenheit war dieses Problem täglich, ein- bis mehrmals täglich.

Wenn sich die Situation ändert, melde ich mich zurück. Bis dahin halte ich dieses Problem mit dem Upgrade für gelöst.

Answer 2

siehe meine Antwort in G1GC long pause with initial-mark

Ihre jede Einstellung sollte einen festen Grund haben, hier zu sein ... und leider einige von ihnen haben nicht z-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)

benutzen Sie bitte/zwicken entsprechend unten genannten Einstellungen optimale Ergebnisse zu erhalten, ich bin Ihnen Baseline geben sich vorwärts zu bewegen, Hoffnung, so werden diese Einstellungen für Sie arbeiten: Java G1 garbage collection in production