G1C strange Full GC behavior

[Darius D.]

Hi,

i am puzzled by strange G1C behavior, everything runs perfectly, G1C
is doing great job keeping heap usage stable etc.

But once in a while we get the following:

...
556882.040: [Full GC 1650M->1552M(3072M), 5.7839410 secs]
 [Times: user=9.77 sys=0.00, real=5.78 secs]
556887.825: [GC concurrent-mark-abort]
...

And of course JVM grinds to halt for 5+s.

Why Full GC is happening when there seems to be no apparent pressure
on heap? And GC resulted in collecting just 98M (sometimes even less)?

At first i thought that app is trying to allocate large amount of
memory, but young gc immediately after Full GC is:

556887.928: [GC pause (young), 0.07898900 secs]
   [Parallel Time:  74.1 ms]
      [GC Worker Start Time (ms):  556887929.4  556887929.4
556887929.4  556887929.5  556887929.5  556887929.6  556887929.6
556887929.7  556887929.7  556887929.7  556887929.8  556887929.8
556887929.9  556887930.0  556887930.0  556887930.1  556887930.2
556887930.2]
      [Update RS (ms):  0.0  34.8  36.9  36.9  8.1  8.0  37.5  30.2
35.0  35.9  0.0  34.2  35.8  35.2  39.8  34.9  32.7  32.7
       Avg:  28.3, Min:   0.0, Max:  39.8]
         [Processed Buffers : 0 52 50 56 25 13 56 57 49 60 0 59 64 62
57 49 47 47
          Sum: 803, Avg: 44, Min: 0, Max: 64]
      [Ext Root Scanning (ms):  73.3  25.1  23.3  23.2  52.4  52.2
23.2  30.1  21.6  24.5  73.0  25.4  23.6  24.1  19.8  24.5  26.4  26.5
       Avg:  32.9, Min:  19.8, Max:  73.3]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0
0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
 0.0  0.0  0.1  0.1  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1]
      [Object Copy (ms):  0.1  3.0  2.5  2.7  2.3  2.4  2.0  2.3  5.9
2.2  0.0  2.8  2.9  2.9  2.6  2.7  3.0  2.9
       Avg:   2.5, Min:   0.0, Max:   5.9]
      [Termination (ms):  0.0  10.5  10.5  10.5  10.5  10.5  10.5
10.5  10.5  10.5  0.0  10.5  10.5  10.5  10.5  10.5  10.5  10.5
       Avg:   9.3, Min:   0.0, Max:  10.5]
         [Termination Attempts : 1 3 2 2 1 2 2 2 2 2 1 2 2 2 2 3 3 2
          Sum: 36, Avg: 2, Min: 1, Max: 3]
      [GC Worker End Time (ms):  556888002.8  556888003.0  556888003.2
 556888002.9  556888002.8  556888002.8  556888003.2  556888003.1
556888003.1  556888003.3  556888003.3  556888002.8  556888002.8
556888003.0  556888002.8  556888002.8  556888003.2  556888002.8]
      [Other:   1.1 ms]
   [Clear CT:   1.3 ms]
   [Other:   3.6 ms]
      [Choose CSet:   0.0 ms]
   [ 1655M->1569M(3072M)]
 [Times: user=1.06 sys=0.00, real=0.08 secs]


Running Sun JDK 1.6 update 27 with the following options:

-Xloggc:/opt/gclog_tomcat.txt -XX:+UseG1GC -XX:+PrintGCDetails
-Xmx3072m -Xms3072m -XX:NewSize=768m -XX:MaxNewSize=768m
-XX:SurvivorRatio=5 -XX:MaxPermSize=768m
-XX:+HeapDumpOnOutOfMemoryError -XX:+UnlockExperimentalVMOptions
-XX:+AggressiveOpts -XX:+UseCompressedOops -XX:+UseFastAccessorMethods
-XX:+DoEscapeAnalysis"


Best Regards,

Darius.