United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-8007036 G1: Too many old regions added to last mixed GC
JDK-8007036 : G1: Too many old regions added to last mixed GC

Details
Type:
Bug
Submit Date:
2013-01-28
Status:
Resolved
Updated Date:
2013-05-08
Project Name:
JDK
Resolved Date:
2013-03-05
Component:
hotspot
OS:
Sub-Component:
gc
CPU:
Priority:
P4
Resolution:
Fixed
Affected Versions:
Fixed Versions:
hs25 (b22)

Related Reports
Backport:
Backport:
Backport:

Sub Tasks

Description
Issue found by the performance team.

At the end of a marking cycle, we know how much reclaimable space there is in each of the old regions. We also know which old regions are reasonable candidates for collection during the next mixed GC phase.

At the end of the next young GC (i.e. the first young to complete after marking), and each subsequent mixed GC, the amount of reclaimable space is checked to see if it's above G1HeapWastePercent. If it is then the next GC will be a mixed GC.

During a mixed GC, we add a number of old regions to the collection set at the start of the collection. The number of regions we add is (currently) based upon the values for G1MixedGCCountTarget and G1OldCSetRegionThresholdPercent. Ideally we would like to collect all of the reasonable candidate regions within G1MixedGCCountTarget mixed GCs but we limit the number of old regions in each mixed GC to be 10% of the heap.

At the start of the final mixed GC, the amount of reclaimable space is still above G1HeapWastePercent, and we will add the same number of regions as in the preceding mixed GCs but that number of regions may result in an amount of reclaimable space that is significantly below G1HeapWastePercent and may result in a mixed GC that is very expansive.

We should be monitoring the amount of uncollected reclaimable bytes while we're adding old regions to the collection set and stop when that amount goes below G1HeapWastePercent.
                                    

Comments
The following log (generated with G1HeapWastePercent = 5 and G1MixedGCCountTarget = 4) from the performance team should illustrate the issue:

The following young GC takes place immediately after marking completes:

870.271: [GC pause (G1 Evacuation Pause) (young)
 870.271: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 163993, predicted base time: 51.86 ms, remaining time: 748.14 ms, target pause time: 800.00 ms]
 870.271: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 324 regions, survivors: 48 regions, predicted young region time: 717.69 ms]
 870.271: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 324 regions, survivors: 48 regions, old: 0 regions, predicted pause time: 769.54 ms, target pause time: 800.00 ms]
 871.023: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 4311 regions, reclaimable: 111975879064 bytes (54.32 %), threshold: 5.00 %]
, 0.7520921 secs]
...

The ergonomics output reports that there are 4311 candidate old regions available and the amount of reclaimable space is 54.32% of the heap, which is much larger than the threshold (G1HeapWastePercent). The net GC is determined to be mixed:

885.693: [GC pause (G1 Evacuation Pause) (mixed)
 885.693: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 234715, predicted base time: 65.50 ms, remaining time: 734.50 ms, target pause time: 800.00 ms]
 885.693: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 273 regions, survivors: 47 regions, predicted young region time: 611.96 ms]
 885.695: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: old CSet region num reached max, old: 615 regions, max: 615 regions]
 885.695: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 615 regions, expensive: 456 regions, min: 1078 regions, remaining time: -543.01 ms]
 885.695: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 273 regions, survivors: 47 regions, old: 615 regions, predicted pause time: 1343.01 ms, target pause time: 800.00 ms]
 886.603: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 159417106432 bytes, allocation request: 0 bytes, threshold: 154618822650 bytes (75.00 %), source: end of GC]

 886.603: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 3696 regions, reclaimable: 92885604896 bytes (45.06 %), threshold: 5.00 %]
, 0.9099798 secs]
...

The ergonomics the min number old regions we can add is 4311 / G1MixedGCCountTarget ( = 1078). The max number of old regions we can add is 615 (10% of the heap). So we add 615 old regions to the collection set. From these 615 old region, the GC above manages to reclaim about 9% of the heap. The remaining amount of reclaimable space amounts to just over 45% of the heap.

This pattern (adding 615 old regions to the collection set) continues. The penultimate mixed GC:

970.845: [GC pause (G1 Evacuation Pause) (mixed)
 970.845: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 249080, predicted base time: 100.01 ms, remaining time: 699.99 ms, target pause time: 800.00 ms]
 970.845: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 280 regions, survivors: 40 regions, predicted young region time: 581.83 ms]
 970.851: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: old CSet region num reached max, old: 615 regions, max: 615 regions]
 970.851: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 615 regions, expensive: 531 regions, min: 1078 regions, remaining time: -865.78 ms]
 970.851: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 280 regions, survivors: 40 regions, old: 615 regions, predicted pause time: 1665.78 ms, target pause time: 800.00 ms]
 972.098: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 621 regions, reclaimable: 10602570736 bytes (5.14 %), threshold: 5.00 %]
, 1.2530701 secs]

still adds 615 old regions to the collection set and the remaining reclaimable bytes is *slightly* above the threshold at 5.14% of the heap. The final mixed GC:

987.157: [GC pause (G1 Evacuation Pause) (mixed)
 987.157: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 280426, predicted base time: 119.98 ms, remaining time: 680.02 ms, target pause time: 800.00 ms]
 987.157: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 280 regions, survivors: 40 regions, predicted young region time: 576.28 ms]
 987.162: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: old CSet region num reached max, old: 615 regions, max: 615 regions]
 987.162: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 615 regions, expensive: 557 regions, min: 1078 regions, remaining time: -1171.18 ms]
 987.162: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 280 regions, survivors: 40 regions, old: 615 regions, predicted pause time: 1971.18 ms, target pause time: 800.00 ms]
 988.543: [G1Ergonomics (Mixed GCs) do not continue mixed GCs, reason: reclaimable percentage lower than threshold, candidate old regions: 6 regions, reclaimable: 134874760 bytes (0.07 %), threshold: 5.00 %]
, 1.3864266 secs]

also adds 615 old regions to the collection set and drops the amount of reclaimable space to a very small fraction of the heap (0.07%). When constructing the collection set we should have stopped adding old regions when remaining amount of reclaimable space dropped below the threshold.
                                     
2013-01-28
With fix:

29.820: [GC pause (G1 Evacuation Pause) (young)
 29.820: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 5808, predicted base time: 14.93 ms, remaining time: 185.07 ms, target pause time: 200.00 ms]
 29.820: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 158 regions, survivors: 28 regions, predicted young region time: 72.25 ms]
 29.820: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 158 regions, survivors: 28 regions, old: 0 regions, predicted pause time: 87.18 ms, target pause time: 200.00 ms]
 29.903: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 38.37 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
 29.903: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 198 regions, reclaimable: 107644008 bytes (10.03 %), threshold: 10.00 %]
, 0.0823079 secs]

The above young gc indicates that there are 198 candidate old regions available with a reclaimable amount of just over the threshold. The next GC is mixed:

29.975: [GC pause (G1 Evacuation Pause) (mixed)
 29.976: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 2849, predicted base time: 9.71 ms, remaining time: 190.29 ms, target pause time: 200.00 ms]
 29.976: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 27 regions, survivors: 24 regions, predicted young region time: 34.25 ms]
 29.976: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: reclaimable percentage not over threshold, old: 1 regions, max: 103 regions, reclaimable: 106774928 bytes (9.94 %), threshold: 10.00 %]
 29.976: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 27 regions, survivors: 24 regions, old: 1 regions, predicted pause time: 45.00 ms, target pause time: 200.00 ms]
 30.021: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 37.40 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)]
 30.021: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 796917760 bytes, allocation request: 0 bytes, threshold: 107374180 bytes (10.00 %), source: end of GC]
 30.021: [G1Ergonomics (Mixed GCs) do not continue mixed GCs, reason: reclaimable percentage not over threshold, candidate old regions: 197 regions, reclaimable: 106774928 bytes (9.94 %), threshold: 10.00 %]
, 0.0453090 secs]

The line:
 29.976: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: reclaimable percentage not over threshold, old: 1 regions, max: 103 regions, reclaimable: 106774928 bytes (9.94 %), threshold: 10.00 %]

indicates that, after adding only one old region, the amount of reclaimable space dropped below the threshold.

                                     
2013-01-28
The amount of remaining reclaimable bytes and whether under G1HeapWastePercent was not considered when adding old regions to the collection set.
                                     
2013-02-04
URL:   http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/27714220e50e
User:  johnc
Date:  2013-03-05 05:30:04 +0000

                                     
2013-03-05
URL:   http://hg.openjdk.java.net/hsx/hsx25/hotspot/rev/27714220e50e
User:  amurillo
Date:  2013-03-08 20:14:20 +0000

                                     
2013-03-08



Hardware and Software, Engineered to Work Together