United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-7143858 G1: Back to back young GCs with the second GC having a minimally sized eden
JDK-7143858 : G1: Back to back young GCs with the second GC having a minimally sized eden

Details
Type:
Bug
Submit Date:
2012-02-08
Status:
Resolved
Updated Date:
2013-04-30
Project Name:
JDK
Resolved Date:
2012-06-02
Component:
hotspot
OS:
generic
Sub-Component:
gc
CPU:
generic
Priority:
P4
Resolution:
Fixed
Affected Versions:
7u4
Fixed Versions:
hs24 (b13)

Related Reports
Backport:
Backport:
Backport:
Duplicate:
Relates:

Sub Tasks

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

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.
                                     
2012-05-21
EVALUATION

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

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

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



Hardware and Software, Engineered to Work Together