[Rare case] G1 mixed GC didn't reclaim garbages in 8u

Fri Feb 7 05:39:28 UTC 2020

Hi All,

I saw a rare case that G1 almost clear nothing in mixed GC but later full GC
 reclaimed 70% of the heap. The version is 8u and is there any bug or is it
an extreme case of floating garbage because of SATB?

The GC log is as below:

2020-02-06T20:07:39.785+0800: 6805.381: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0381100 secs]
   [Parallel Time: 32.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 6805383.4, Avg: 6805383.5, Max: 6805383.5, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 7.4, Avg: 12.1, Max: 19.6, Diff: 12.2, Sum: 97.0]
      [Update RS (ms): Min: 2.8, Avg: 6.3, Max: 11.1, Diff: 8.3, Sum: 50.7]
         [Processed Buffers: Min: 48, Avg: 116.9, Max: 180, Diff: 132, Sum: 935]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.7, Avg: 13.6, Max: 17.6, Diff: 7.9, Sum: 109.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 32.1, Avg: 32.2, Max: 32.2, Diff: 0.1, Sum: 257.5]
      [GC Worker End (ms): Min: 6805415.6, Avg: 6805415.6, Max: 6805415.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 5.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 608.0M(608.0M)->0.0B(608.0M) Survivors: 96.0M->96.0M Heap: 13.8G(14.2G)->13.2G(14.2G)]
 [Times: user=0.22 sys=0.00, real=0.04 secs]
2020-02-06T20:07:39.825+0800: 6805.421: [GC concurrent-root-region-scan-start]
2020-02-06T20:07:39.826+0800: 6805.422: Total time for which application threads were stopped: 0.0512361 seconds, Stopping threads took: 0.0009971 seconds
2020-02-06T20:07:39.845+0800: 6805.441: [GC concurrent-root-region-scan-end, 0.0199532 secs]
2020-02-06T20:07:39.845+0800: 6805.441: [GC concurrent-mark-start]
2020-02-06T20:07:43.459+0800: 6809.055: [GC concurrent-mark-end, 3.6139728 secs]
2020-02-06T20:07:43.467+0800: 6809.063: [GC remark 2020-02-06T20:07:43.467+0800: 6809.063: [Finalize Marking, 0.0027913 secs] 2020-02-06T20:07:43.470+0800: 6809.066: [GC ref-proc, 0.0141510 secs] 2020-02-06T20:07:43.484+0800: 6809.080: [Unloading, 0.0562292 secs], 0.0987990 secs]
 [Times: user=0.60 sys=0.01, real=0.10 secs]
2020-02-06T20:07:43.568+0800: 6809.164: Total time for which application threads were stopped: 0.1087168 seconds, Stopping threads took: 0.0008774 seconds
2020-02-06T20:07:43.576+0800: 6809.172: [GC cleanup 13G->13G(14G), 0.0128258 secs]
 [Times: user=0.08 sys=0.01, real=0.01 secs]
2020-02-06T20:07:43.590+0800: 6809.186: Total time for which application threads were stopped: 0.0223063 seconds, Stopping threads took: 0.0005304 seconds
2020-02-06T20:07:45.145+0800: 6810.741: [GC pause (G1 Evacuation Pause) (young), 0.0299645 secs]
   [Parallel Time: 24.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 6810743.7, Avg: 6810744.1, Max: 6810746.8, Diff: 3.1]
      [Ext Root Scanning (ms): Min: 5.5, Avg: 9.0, Max: 15.3, Diff: 9.8, Sum: 72.2]
      [Update RS (ms): Min: 2.8, Avg: 6.8, Max: 9.3, Diff: 6.5, Sum: 54.2]
         [Processed Buffers: Min: 58, Avg: 120.5, Max: 175, Diff: 117, Sum: 964]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 6.4, Avg: 8.4, Max: 9.7, Diff: 3.3, Sum: 66.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [GC Worker Total (ms): Min: 21.5, Avg: 24.3, Max: 24.7, Diff: 3.1, Sum: 194.0]
      [GC Worker End (ms): Min: 6810768.3, Avg: 6810768.3, Max: 6810768.4, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 4.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 608.0M(608.0M)->0.0B(608.0M) Survivors: 96.0M->96.0M Heap: 13.8G(14.2G)->13.3G(14.2G)]
 [Times: user=0.17 sys=0.00, real=0.03 secs]
2020-02-06T20:07:45.178+0800: 6810.774: Total time for which application threads were stopped: 0.0420222 seconds, Stopping threads took: 0.0009371 seconds
2020-02-06T20:07:47.186+0800: 6812.782: Total time for which application threads were stopped: 0.0081580 seconds, Stopping threads took: 0.0009037 seconds
2020-02-06T20:07:51.031+0800: 6816.627: [GC pause (G1 Evacuation Pause) (mixed), 0.0327771 secs]
   [Parallel Time: 27.2 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 6816629.1, Avg: 6816629.2, Max: 6816629.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 4.9, Avg: 7.6, Max: 15.4, Diff: 10.5, Sum: 60.8]
      [Update RS (ms): Min: 2.8, Avg: 6.3, Max: 9.1, Diff: 6.2, Sum: 50.8]
         [Processed Buffers: Min: 18, Avg: 124.9, Max: 224, Diff: 206, Sum: 999]
      [Scan RS (ms): Min: 0.5, Avg: 0.8, Max: 1.2, Diff: 0.6, Sum: 6.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 6.4, Avg: 12.4, Max: 17.4, Diff: 11.0, Sum: 99.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 27.1, Avg: 27.1, Max: 27.2, Diff: 0.1, Sum: 216.9]
      [GC Worker End (ms): Min: 6816656.3, Avg: 6816656.3, Max: 6816656.3, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 5.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.2 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 608.0M(608.0M)->0.0B(608.0M) Survivors: 96.0M->96.0M Heap: 13.8G(14.2G)->13.2G(14.2G)]
 [Times: user=0.21 sys=0.01, real=0.04 secs]
2020-02-06T20:07:51.066+0800: 6816.662: Total time for which application threads were stopped: 0.0449305 seconds, Stopping threads took: 0.0009496 seconds
2020-02-06T20:07:58.095+0800: 6823.691: [GC pause (G1 Evacuation Pause) (young), 0.0297937 secs]
   [Parallel Time: 24.3 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 6823693.1, Avg: 6823693.1, Max: 6823693.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 4.9, Avg: 7.3, Max: 15.6, Diff: 10.7, Sum: 58.1]
      [Update RS (ms): Min: 5.6, Avg: 7.4, Max: 9.1, Diff: 3.5, Sum: 58.9]
         [Processed Buffers: Min: 30, Avg: 124.6, Max: 163, Diff: 133, Sum: 997]
      [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 2.4, Avg: 9.5, Max: 13.4, Diff: 11.0, Sum: 76.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 24.2, Avg: 24.2, Max: 24.3, Diff: 0.1, Sum: 193.9]
      [GC Worker End (ms): Min: 6823717.4, Avg: 6823717.4, Max: 6823717.4, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.3 ms]
   [Other: 5.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.2 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 608.0M(608.0M)->0.0B(608.0M) Survivors: 96.0M->96.0M Heap: 13.8G(14.2G)->13.3G(14.2G)]

2020-02-06T20:08:18.256+0800: 6843.852: [Full GC (Allocation Failure)  14G->4027M(14G), 7.5914236 secs]
   [Eden: 0.0B(704.0M)->0.0B(4480.0M) Survivors: 0.0B->0.0B Heap: 14.0G(14.2G)->4027.5M(14.2G)], [Metaspace: 401632K->401608K(1411072K)]
 [Times: user=11.26 sys=0.18, real=7.59 secs]

Thanks,
Liang