JDK-7143858 : G1: Back to back young GCs with the second GC having a minimally sized eden
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 7u4
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2012-02-08
  • Updated: 2019-08-01
  • Resolved: 2012-06-02
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 7 JDK 8 Other
7u40Fixed 8Fixed hs24Fixed
Related Reports
Duplicate :  
Relates :  
Relates :  
Relates :  
Description
While running some G1 performance tests, Charlie Hunt discovered some unusual young GC pauses where the eden size would suddenly drop from 5G in one pause to 8M in the next.

The following log snippet illustrates the issue:

---------------------
Here's the GC before, "the GC", and the GC after that drop in Eden.

I'm trying to understand why we dropped the size of Eden.   The only thing that stands out to me is in "the GC" where the eden size is dropped, the "Update RS" times are about 10x larger than the before or after GCs.   Does G1 happen to know, or predict, how much time it's going to spend in an "Update RS" on the next GC?

Here's the GCs:

136.678: [GC pause (young), 0.13907365 secs]
   [Parallel Time: 129.2 ms]
      [GC Worker Start (ms):  136677.9  136678.0  136678.0  136678.0  136678.0  136678.0  136678.0  136678.0  136678.0  136678.0
       Avg: 136678.0, Min: 136677.9, Max: 136678.0, Diff:   0.1]
      [Ext Root Scanning (ms):  1.0  8.3  1.0  1.0  1.0  1.0  1.3  1.0  0.9  0.9
       Avg:   1.7, Min:   0.9, Max:   8.3, Diff:   7.5]
      [Update RS (ms):  1.1  0.0  1.0  1.0  1.5  1.3  0.9  1.5  1.0  1.0
       Avg:   1.0, Min:   0.0, Max:   1.5, Diff:   1.5]
         [Processed Buffers : 2 0 8 21 3 2 1 1 5 1
          Sum: 44, Avg: 4, Min: 0, Max: 21, Diff: 21]
      [Scan RS (ms):  6.2  0.0  6.3  6.3  5.7  5.9  6.1  5.7  6.3  6.3
       Avg:   5.5, Min:   0.0, Max:   6.3, Diff:   6.3]
      [Object Copy (ms):  119.3  119.2  119.3  119.3  119.4  119.3  119.3  119.3  119.3  119.4
       Avg: 119.3, Min: 119.2, Max: 119.4, Diff:   0.2]
      [Termination (ms):  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, Diff:   0.0]
         [Termination Attempts : 1 1 1 1 1 1 1 1 1 1
          Sum: 10, Avg: 1, Min: 1, Max: 1, Diff: 0]
      [GC Worker End (ms):  136805.5  136805.6  136805.6  136805.6  136805.6  136805.6  136805.5  136805.5  136805.6  136805.5
       Avg: 136805.6, Min: 136805.5, Max: 136805.6, Diff:   0.1]
      [GC Worker (ms):  127.6  127.6  127.6  127.6  127.6  127.6  127.5  127.5  127.6  127.5
       Avg: 127.6, Min: 127.5, Max: 127.6, Diff:   0.1]
      [GC Worker Other (ms):  1.6  1.6  1.6  1.6  1.7  1.7  1.7  1.7  1.7  1.7
       Avg:   1.7, Min:   1.6, Max:   1.7, Diff:   0.1]
   [Clear CT:   0.9 ms]
   [Other:   9.0 ms]
      [Choose CSet:   0.1 ms]
      [Ref Proc:   0.2 ms]
      [Ref Enq:   0.0 ms]
      [Free CSet:   8.3 ms]
   [Eden: 5040M(5040M)->0B(5040M) Survivors: 280M->280M Heap: 5722M(26624M)->685M(26624M)]
 [Times: user=1.29 sys=0.00, real=0.14 secs]
136.818: [GC pause (young), 0.16131867 secs]
   [Parallel Time: 159.6 ms]
      [GC Worker Start (ms):  136817.6  136817.6  136817.6  136817.6  136817.6  136817.6  136817.6  136817.6  136817.6  136817.6
       Avg: 136817.6, Min: 136817.6, Max: 136817.6, Diff:   0.1]
      [Ext Root Scanning (ms):  1.0  1.0  1.0  1.0  1.0  1.3  0.9  1.0  3.9  0.9
       Avg:   1.3, Min:   0.9, Max:   3.9, Diff:   3.0]
      [Update RS (ms):  13.2  13.3  13.1  16.3  13.9  13.7  13.5  13.1  11.2  13.8
       Avg:  13.5, Min:  11.2, Max:  16.3, Diff:   5.1]
         [Processed Buffers : 16 14 9 10 10 7 12 20 5 11
          Sum: 114, Avg: 11, Min: 5, Max: 20, Diff: 15]
      [Scan RS (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.1  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1, Diff:   0.1]
      [Object Copy (ms):  143.7  142.8  142.8  139.8  142.1  142.2  142.4  142.9  141.7  142.3
       Avg: 142.3, Min: 139.8, Max: 143.7, Diff:   3.9]
      [Termination (ms):  0.0  0.9  1.0  0.8  1.0  0.7  1.1  0.9  1.2  1.0
       Avg:   0.9, Min:   0.0, Max:   1.2, Diff:   1.2]
         [Termination Attempts : 1 3578 3521 3176 3473 2622 3593 3096 4064 3232
          Sum: 30356, Avg: 3035, Min: 1, Max: 4064, Diff: 4063]
      [GC Worker End (ms):  136975.6  136975.6  136975.6  136975.6  136975.6  136975.6  136975.6  136975.6  136975.6  136975.6
       Avg: 136975.6, Min: 136975.6, Max: 136975.6, Diff:   0.0]
      [GC Worker (ms):  158.0  158.0  158.0  158.0  158.0  158.0  158.0  158.0  157.9  158.0
       Avg: 158.0, Min: 157.9, Max: 158.0, Diff:   0.1]
      [GC Worker Other (ms):  1.6  1.6  1.6  1.6  1.7  1.7  1.7  1.7  1.7  1.7
       Avg:   1.7, Min:   1.6, Max:   1.7, Diff:   0.1]
   [Clear CT:   0.1 ms]
   [Other:   1.6 ms]
      [Choose CSet:   0.0 ms]
      [Ref Proc:   0.1 ms]
      [Ref Enq:   0.0 ms]
      [Free CSet:   0.7 ms]
   [Eden: 8192K(5040M)->0B(5032M) Survivors: 280M->288M Heap: 686M(26624M)->687M(26624M)]
 [Times: user=1.57 sys=0.01, real=0.16 secs]
141.846: [GC pause (young), 0.15612571 secs]
   [Parallel Time: 151.1 ms]
      [GC Worker Start (ms):  141845.9  141845.9  141845.9  141845.9  141845.9  141845.9  141845.9  141847.8  141847.8  141847.9
       Avg: 141846.5, Min: 141845.9, Max: 141847.9, Diff:   2.1]
      [Ext Root Scanning (ms):  1.6  1.5  3.0  1.3  1.6  2.6  1.3  0.0  0.0  0.0
       Avg:   1.3, Min:   0.0, Max:   3.0, Diff:   3.0]
      [Update RS (ms):  1.1  2.3  0.0  1.7  1.2  0.1  1.4  0.9  0.9  1.0
       Avg:   1.1, Min:   0.0, Max:   2.3, Diff:   2.3]
         [Processed Buffers : 20 1 0 1 33 19 9 8 1 2
          Sum: 94, Avg: 9, Min: 0, Max: 33, Diff: 33]
      [Scan RS (ms):  6.1  4.8  5.6  6.3  6.5  5.8  5.8  5.8  6.5  5.6
       Avg:   5.9, Min:   4.8, Max:   6.5, Diff:   1.7]
      [Object Copy (ms):  138.4  138.1  138.1  137.4  137.5  138.2  138.1  138.0  139.2  140.1
       Avg: 138.3, Min: 137.4, Max: 140.1, Diff:   2.7]
      [Termination (ms):  2.0  2.5  2.4  2.4  2.4  2.4  2.4  2.5  0.5  0.3
       Avg:   2.0, Min:   0.3, Max:   2.5, Diff:   2.2]
         [Termination Attempts : 1 1982 1849 1803 1583 1467 1810 1922 1628 1059
          Sum: 15104, Avg: 1510, Min: 1, Max: 1982, Diff: 1981]
      [GC Worker End (ms):  141995.0  141995.0  141995.0  141995.0  141995.0  141995.0  141995.0  141995.0  141995.0  141995.0
       Avg: 141995.0, Min: 141995.0, Max: 141995.0, Diff:   0.0]
      [GC Worker (ms):  149.2  149.2  149.1  149.1  149.1  149.1  149.1  147.2  147.2  147.1
       Avg: 148.6, Min: 147.1, Max: 149.2, Diff:   2.1]
      [GC Worker Other (ms):  2.0  2.0  2.0  2.0  2.0  2.0  2.0  3.9  3.9  4.0
       Avg:   2.6, Min:   2.0, Max:   4.0, Diff:   2.1]
   [Clear CT:   0.7 ms]
   [Other:   4.3 ms]
      [Choose CSet:   0.1 ms]
      [Ref Proc:   0.2 ms]
      [Ref Enq:   0.0 ms]
      [Free CSet:   3.7 ms]
   [Eden: 5032M(5032M)->0B(5032M) Survivors: 288M->288M Heap: 5719M(26624M)->692M(26624M)]
 [Times: user=1.49 sys=0.00, real=0.16 secs] 

---------------------------

In the above snippet:
* the Eden in the first pause is sized at 5040M.
* The first pause has an elapsed duration of 139.1 ms.
* The time stamp on the first pause is 136.678 - which means it ended at 136.8171.

* The Eden in the second pause is only 8M (which is one region given the heap sizing parameters).
* The timestamp of the second pause is 136.818

This indicates that the application did not run between these two GCs.

Comments
EVALUATION http://hg.openjdk.java.net/lambda/lambda/hotspot/rev/1d478c993020
29-06-2012

SUGGESTED FIX Stall allocating thread until after the GCLocker Initiated GC has been peformed. Skip the GC and retry the allocation attempt instead.
30-05-2012

EVALUATION http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/1d478c993020
29-05-2012

EVALUATION Race between allocating thread scheduling a GC and the last thread leaving a critical region scheduling a GCLocker Initiated GC. The allocating thread wins and sees that the GCLocker is no longer active and schedules its GC.
21-05-2012