JDK-8210193 : [TESTBUG]gc/g1/mixedgc/TestOldGenCollectionUsage.java fails intermittently with OutOfMemoryError in CDS mode
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 12
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-08-30
  • Updated: 2019-05-28
  • Resolved: 2018-09-13
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 12
12 b12Fixed
Related Reports
Duplicate :  
JDK-8211079 - gc/g1/mixedgc/TestOldGenCollectionUsage.java intermittently fails with Premature mixed collections(s)
Relates :  
JDK-8196611 - [Graal] Tests unaware of objects allocation triggered by Graal
Relates :  
JDK-8202951 - Implementation of JEPJDK-8204247: Include default CDS (Class Data Sharing) archive in JDK binary
Relates :  
JDK-8195115 - G1 Old Gen MemoryPool CollectionUsage.used values don't reflect mixed GC results
Description
gc/g1/mixedgc/TestOldGenCollectionUsage.java fails intermittently with OutOfMemoryError when running with CDS enabled.

[0.028s][info][gc] Using G1
Monitor G1 Old Gen pool with G1 Young Generation collector.
Found pool: G1 Old Gen
Found collector: G1 Young Generation
[39.355s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 5M->2M(12M) 57.183ms
[39.392s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 3M->3M(12M) 35.974ms
[39.394s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 4M->5M(12M) 1.331ms
[39.396s][info][gc] GC(3) Pause Young (Normal) (WhiteBox Initiated Young GC) 6M->6M(12M) 1.750ms
[39.399s][info][gc] GC(4) Pause Young (Normal) (WhiteBox Initiated Young GC) 6M->6M(12M) 1.342ms
G1 Old Gen: usage after GC = 0
G1 Young Generation: collection count = 5
G1 Young Generation: collection time  = 96
[40.295s][info][gc] GC(5) Pause Young (Concurrent Start) (WhiteBox Initiated Concurrent Mark) 6M->6M(12M) 2.016ms
[40.296s][info][gc] GC(6) Concurrent Cycle
[40.368s][info][gc] GC(6) Pause Remark 6M->6M(12M) 60.726ms
[40.377s][info][gc] GC(6) Pause Cleanup 6M->6M(12M) 0.138ms
[40.378s][info][gc] GC(6) Concurrent Cycle 82.068ms
[40.381s][info][gc] GC(7) Pause Young (Prepare Mixed) (WhiteBox Initiated Young GC) 6M->6M(12M) 2.505ms
Allocating new objects to provoke mixed GC
[40.383s][info][gc] GC(8) Pause Young (Mixed) (G1 Evacuation Pause) 7M->6M(12M) 1.609ms
[40.402s][info][gc] GC(9) Pause Young (Mixed) (G1 Evacuation Pause) 7M->6M(12M) 18.973ms
[40.436s][info][gc] GC(10) To-space exhausted
[40.436s][info][gc] GC(10) Pause Young (Mixed) (G1 Evacuation Pause) 8M->10M(12M) 33.323ms
[40.572s][info][gc] GC(11) Pause Full (G1 Evacuation Pause) 10M->7M(12M) 133.504ms
[40.574s][info][gc] GC(12) Pause Young (Normal) (G1 Evacuation Pause) 8M->8M(12M) 0.861ms
[40.812s][info][gc] GC(13) To-space exhausted
[40.812s][info][gc] GC(13) Pause Young (Normal) (G1 Evacuation Pause) 9M->9M(12M) 3.171ms
[40.942s][info][gc] GC(14) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 129.230ms
[41.068s][info][gc] GC(15) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 124.669ms
[41.070s][info][gc] GC(16) Pause Young (Normal) (G1 Evacuation Pause) 9M->9M(12M) 0.881ms
[41.209s][info][gc] GC(17) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 138.452ms
[41.335s][info][gc] GC(18) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 125.504ms
[41.337s][info][gc] GC(19) Pause Young (Normal) (G1 Evacuation Pause) 9M->9M(12M) 0.728ms
[41.460s][info][gc] GC(20) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 121.937ms
[41.572s][info][gc] GC(21) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 112.300ms
[41.574s][info][gc] GC(22) Pause Young (Normal) (G1 Evacuation Pause) 9M->9M(12M) 0.874ms
[41.734s][info][gc] GC(23) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 159.758ms
[41.867s][info][gc] GC(24) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 132.231ms
[41.870s][info][gc] GC(25) Pause Young (Normal) (G1 Evacuation Pause) 9M->9M(12M) 1.038ms
[42.013s][info][gc] GC(26) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 142.617ms
[42.155s][info][gc] GC(27) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 141.286ms
[42.157s][info][gc] GC(28) Pause Young (Normal) (G1 Evacuation Pause) 9M->9M(12M) 1.221ms
[42.295s][info][gc] GC(29) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 137.493ms
[42.433s][info][gc] GC(30) Pause Full (G1 Evacuation Pause) 9M->9M(12M) 136.979ms
[42.437s][info][gc] GC(31) Pause Young (Normal) (G1 Evacuation Pause) 9M->9M(12M) 3.065ms
[42.570s][info][gc] GC(32) Pause Full (G1 Evacuation Pause) 9M->2M(12M) 132.926ms
----------System.err:(6/249)----------
java.lang.OutOfMemoryError: Java heap space
Comments
[~phh]Thanks for taking a look of the change! I'll update TestLogging.java also.
12-09-2018
This looks reasonable. I used TestLogging.java in the same directory as a template, so I recommend taking a look at it too.
12-09-2018
To address the failure, the java heap size can be increased to 14M. That still inlines with the test purpose, which checks old gen's CollectionUsage.used > 0 with objects live in old gen. To prevent future issue, the test can also be modified to handle the OOM. diff --git a/test/hotspot/jtreg/gc/g1/mixedgc/TestOldGenCollectionUsage.java b/test/hotspot/jtreg/gc/g1/mixedgc/TestOldGenCollectionUsage.java --- a/test/hotspot/jtreg/gc/g1/mixedgc/TestOldGenCollectionUsage.java +++ b/test/hotspot/jtreg/gc/g1/mixedgc/TestOldGenCollectionUsage.java @@ -33,7 +33,8 @@ * @modules java.management * @build sun.hotspot.WhiteBox * @run driver ClassFileInstaller sun.hotspot.WhiteBox - * @run main/othervm -Xbootclasspath/a:. -XX:+UseG1GC -XX:+UnlockExperimentalVMOptions -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -verbose:gc -XX:SurvivorRatio=1 -Xmx12m -Xms12m -XX:MaxTenuringThreshold=1 -XX:InitiatingHeapOccupancyPercent=100 -XX:-G1UseAdaptiveIHOP -XX:G1MixedGCCountTarget=4 -XX:MaxGCPauseMillis=30000 -XX:G1HeapRegionSize=1m -XX:G1HeapWastePercent=0 -XX:G1MixedGCLiveThresholdPercent=100 TestOldGenCollectionUsage + * @run main/othervm -Xbootclasspath/a:. -XX:+UseG1GC -XX:+UnlockExperimentalVMOptions + * -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -verbose:gc -XX:SurvivorRatio=1 -Xmx14m -Xms14m -XX:MaxTenuringThreshold=1 -XX:InitiatingHeapOccupancyPercent=100 -XX:-G1UseAdaptiveIHOP -XX:G1MixedGCCountTarget=4 -XX:MaxGCPauseMillis=30000 -XX:G1HeapRegionSize=1m -XX:G1HeapWastePercent=0 -XX:G1MixedGCLiveThresholdPercent=100 TestOldGenCollectionUsage */ import jdk.test.lib.Asserts; @@ -209,7 +210,15 @@ // Provoke a mixed collection. G1MixedGCLiveThresholdPercent=100 // guarantees that full old gen regions will be included. for (int i = 0; i < (ALLOCATION_COUNT * 20); i++) { - newObjects.add(new byte[ALLOCATION_SIZE]); + try { + newObjects.add(new byte[ALLOCATION_SIZE]); + } catch (OutOfMemoryError e) { + newObjects.clear(); + WB.youngGC(); + WB.youngGC(); + System.out.println("OutOfMemoryError is reported, stop allocating new objects"); + break; + } } // check that liveOldObjects still alive Asserts.assertTrue(WB.isObjectInOldGen(liveOldObjects),
12-09-2018
I think this is a test issue as it makes assumption about the java heap usage.
12-09-2018
Similar OOM is also reported in JDK-8196611, in which case graal is enabled and additional java objects are allocated.
12-09-2018
Here is what the test does: 1. Allocate: 15 long lived byte arrays with length = 20000x5 15 short lived byte arrays with length = 20000x5 2. Do young collections 3. Allocate long lived 300 byte arrays with length = 20000 When OOM occurs, it happens during the third step. On various test platforms, the java heap space needed for the long lived objects is between 8M and 11M (the differences are possibly due to alignment). The test uses 12M java heap, which is just large enough for accommodating the long lived object. With the default CDS enabled, there are GC regions used for the open and closed archive heap objects. Each region is 1M (2 regions are used). Currently, the size of the closed archive objects is about 430K and the size of the open archive objects is about 300K. The rest of the space within those regions are filled with dummy objects and cannot be used for other objects. The archive region filling is intentional. Therefore, in some cases, the heap requirement can be >12M and triggers the OOM. That's the reason why the test does not always fail with the default CDS enabled.
12-09-2018