8237079: gc/g1/mixedgc/TestLogging.java fails with "Pause Young (Mixed) (G1 Evacuation Pause) not found"

Factor out multiple attempts at forcing a mixed gc into a single one and update the tests to use the new code. Change command line arguments for the tests to further decrease the possibility of failures.

Reviewed-by: lkorinth, kbarrett
This commit is contained in:
Thomas Schatzl 2020-01-23 14:42:49 +01:00
parent da7cebabb2
commit ffcc582601
4 changed files with 156 additions and 270 deletions

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2015, 2018, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2015, 2020, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -21,12 +21,22 @@
* questions.
*/
package gc.g1.mixedgc;
import java.util.ArrayList;
import java.util.Collections;
import java.util.List;
import gc.testlibrary.g1.MixedGCProvoker;
import jdk.test.lib.process.OutputAnalyzer;
import jdk.test.lib.process.ProcessTools;
/*
* @test TestLogging
* @summary Check that a mixed GC is reflected in the gc logs
* @requires vm.gc.G1
* @requires vm.opt.MaxGCPauseMillis == "null"
* @library /test/lib
* @library /test/lib /
* @modules java.base/jdk.internal.misc
* @modules java.management
* @build sun.hotspot.WhiteBox
@ -34,17 +44,6 @@
* @run driver gc.g1.mixedgc.TestLogging
*/
package gc.g1.mixedgc;
import jdk.test.lib.process.OutputAnalyzer;
import jdk.test.lib.process.ProcessTools;
import jdk.test.lib.Asserts;
import sun.hotspot.WhiteBox;
import java.util.ArrayList;
import java.util.List;
import java.util.Collections;
/**
* Test spawns MixedGCProvoker in a separate VM and expects to find a message
* telling that a mixed gc has happened
@ -55,9 +54,8 @@ public class TestLogging {
"-XX:+UnlockExperimentalVMOptions",
"-XX:+UnlockDiagnosticVMOptions",
"-XX:+WhiteBoxAPI",
"-XX:SurvivorRatio=1", // Survivor-to-eden ratio is 1:1
"-Xms10M", "-Xmx10M",
"-XX:MaxTenuringThreshold=1", // promote objects after first gc
"-Xms10M", "-Xmx10M", "-XX:NewSize=2M", "-XX:MaxNewSize=2M",
"-XX:+AlwaysTenure", // surviving promote objects immediately
"-XX:InitiatingHeapOccupancyPercent=100", // set initial CMC threshold and disable adaptive IHOP
"-XX:-G1UseAdaptiveIHOP", // to avoid additional concurrent cycles caused by ergonomics
"-XX:G1MixedGCCountTarget=4",
@ -65,14 +63,11 @@ public class TestLogging {
"-XX:G1HeapRegionSize=1m", "-XX:G1HeapWastePercent=0",
"-XX:G1MixedGCLiveThresholdPercent=100"};
public static final int ALLOCATION_SIZE = 20000;
public static final int ALLOCATION_COUNT = 15;
public static void main(String args[]) throws Exception {
// Test turns logging on by giving -Xlog:gc flag
test("-Xlog:gc");
test("-Xlog:gc,gc+heap=debug");
// Test turns logging on by giving -Xlog:gc=debug flag
test("-Xlog:gc=debug");
test("-Xlog:gc=debug,gc+heap=debug");
}
private static void test(String vmFlag) throws Exception {
@ -80,7 +75,7 @@ public class TestLogging {
OutputAnalyzer output = spawnMixedGCProvoker(vmFlag);
System.out.println(output.getStdout());
output.shouldHaveExitValue(0);
output.shouldContain("Pause Young (Mixed) (G1 Evacuation Pause)");
output.shouldContain("Pause Young (Mixed)");
}
/**
@ -93,7 +88,7 @@ public class TestLogging {
List<String> testOpts = new ArrayList<>();
Collections.addAll(testOpts, COMMON_OPTIONS);
Collections.addAll(testOpts, extraFlags);
testOpts.add(MixedGCProvoker.class.getName());
testOpts.add(RunMixedGC.class.getName());
System.out.println(testOpts);
ProcessBuilder pb = ProcessTools.createJavaProcessBuilder(false,
testOpts.toArray(new String[testOpts.size()]));
@ -101,82 +96,10 @@ public class TestLogging {
}
}
/**
* Utility class to guarantee a mixed GC. The class allocates several arrays and
* promotes them to the oldgen. After that it tries to provoke mixed GC by
* allocating new objects.
*
* The necessary condition for guaranteed mixed GC is running MixedGCProvoker is
* running in VM with the following flags: -XX:MaxTenuringThreshold=1, -Xms10M,
* -Xmx10M, -XX:G1MixedGCLiveThresholdPercent=100, -XX:G1HeapWastePercent=0,
* -XX:G1HeapRegionSize=1m
*/
class MixedGCProvoker {
private static final WhiteBox WB = WhiteBox.getWhiteBox();
private static final List<byte[]> liveOldObjects = new ArrayList<>();
private static final List<byte[]> newObjects = new ArrayList<>();
private static void allocateOldObjects() throws Exception {
List<byte[]> deadOldObjects = new ArrayList<>();
// Allocates buffer and promotes it to the old gen. Mix live and dead old
// objects
for (int i = 0; i < TestLogging.ALLOCATION_COUNT; ++i) {
liveOldObjects.add(new byte[TestLogging.ALLOCATION_SIZE * 5]);
deadOldObjects.add(new byte[TestLogging.ALLOCATION_SIZE * 5]);
}
// need only 2 promotions to promote objects to the old gen
WB.youngGC();
WB.youngGC();
// check it is promoted & keep alive
Asserts.assertTrue(WB.isObjectInOldGen(liveOldObjects),
"List of the objects is suppose to be in OldGen");
Asserts.assertTrue(WB.isObjectInOldGen(deadOldObjects),
"List of the objects is suppose to be in OldGen");
}
/**
* Waits until Concurent Mark Cycle finishes
* @param wb Whitebox instance
* @param sleepTime sleep time
*/
public static void waitTillCMCFinished(WhiteBox wb, int sleepTime) {
while (wb.g1InConcurrentMark()) {
if (sleepTime > -1) {
try {
Thread.sleep(sleepTime);
} catch (InterruptedException e) {
System.out.println("Got InterruptedException while waiting for ConcMarkCycle to finish");
}
}
}
}
public static void main(String args[]) throws Exception {
// allocate old objects
allocateOldObjects();
waitTillCMCFinished(WB, 0);
WB.g1StartConcMarkCycle();
waitTillCMCFinished(WB, 0);
WB.youngGC();
System.out.println("Allocating new objects to provoke mixed GC");
// allocate more objects to provoke GC
for (int i = 0; i < (TestLogging.ALLOCATION_COUNT * 20); i++) {
try {
newObjects.add(new byte[TestLogging.ALLOCATION_SIZE]);
} catch (OutOfMemoryError e) {
newObjects.clear();
WB.youngGC();
WB.youngGC();
break;
}
}
// check that liveOldObjects still alive
Asserts.assertTrue(WB.isObjectInOldGen(liveOldObjects),
"List of the objects is suppose to be in OldGen");
class RunMixedGC {
public static void main(String[] args) {
final int MB = 1024 * 1024;
MixedGCProvoker.allocateAndProvokeMixedGC(MB);
}
}

View File

@ -23,32 +23,38 @@
package gc.g1.mixedgc;
import static sun.hotspot.WhiteBox.getWhiteBox;
import java.lang.management.*;
import java.util.ArrayList;
import java.util.List;
import gc.testlibrary.g1.MixedGCProvoker;
/*
* @test TestOldGenCollectionUsage.java
* @bug 8195115
* @summary G1 Old Gen's CollectionUsage.used is zero after mixed GC which is incorrect
* @key gc
* @requires vm.gc.G1
* @library /test/lib
* @library /test/lib /
* @modules java.base/jdk.internal.misc
* @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 -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 gc.g1.mixedgc.TestOldGenCollectionUsage
* @run main/othervm -Xbootclasspath/a:. -XX:+UseG1GC -XX:+UnlockExperimentalVMOptions -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -verbose:gc -XX:NewSize=2m -XX:MaxNewSize=2m -Xmx14m -Xms14m -XX:+AlwaysTenure -XX:InitiatingHeapOccupancyPercent=100 -XX:-G1UseAdaptiveIHOP -XX:G1MixedGCCountTarget=4 -XX:MaxGCPauseMillis=30000 -XX:G1HeapRegionSize=1m -XX:G1HeapWastePercent=0 -XX:G1MixedGCLiveThresholdPercent=100 gc.g1.mixedgc.TestOldGenCollectionUsage
*/
import jdk.test.lib.Asserts;
import sun.hotspot.WhiteBox;
import java.util.ArrayList;
import java.util.List;
import java.lang.management.*;
// 8195115 says that for the "G1 Old Gen" MemoryPool, CollectionUsage.used
// is zero for G1 after a mixed collection, which is incorrect.
// is zero for G1 after a mixed collection, which is incorrect. We can not guarantee
// that we start with an old gen occupancy of zero though due to allocation during
// initialization. We check for "increases during mixed gc" instead.
public class TestOldGenCollectionUsage {
private static final int HeapRegionSize = 1024 * 1024;
private static final int ObjectSize = 20_000;
private String poolName = "G1 Old Gen";
private String collectorName = "G1 Young Generation";
@ -95,15 +101,13 @@ public class TestOldGenCollectionUsage {
throw new RuntimeException(collectorName + " not found, test with -XX:+UseG1GC");
}
MixedGCProvoker gcProvoker = new MixedGCProvoker();
gcProvoker.allocateOldObjects();
getWhiteBox().fullGC(); // Make sure the heap is in a known state.
// Verify no non-zero result was stored
long usage = pool.getCollectionUsage().getUsed();
System.out.println(poolName + ": usage after GC = " + usage);
if (usage > 0) {
throw new RuntimeException("Premature mixed collections(s)");
}
var liveOldObjects = new ArrayList<byte[]>();
MixedGCProvoker.allocateOldObjects(liveOldObjects, HeapRegionSize, ObjectSize);
long baseUsage = pool.getCollectionUsage().getUsed();
System.out.println(poolName + ": usage after GC = " + baseUsage);
// Verify that collections were done
long collectionCount = collector.getCollectionCount();
@ -119,12 +123,12 @@ public class TestOldGenCollectionUsage {
throw new RuntimeException("Collector has not run");
}
gcProvoker.provokeMixedGC();
MixedGCProvoker.provokeMixedGC(liveOldObjects);
usage = pool.getCollectionUsage().getUsed();
long usage = pool.getCollectionUsage().getUsed();
System.out.println(poolName + ": usage after GC = " + usage);
if (usage <= 0) {
throw new RuntimeException(poolName + " found with zero usage");
if (usage <= baseUsage) {
throw new RuntimeException(poolName + " found not updating usage");
}
long newCollectionCount = collector.getCollectionCount();
@ -142,87 +146,5 @@ public class TestOldGenCollectionUsage {
System.out.println("Test passed.");
}
/**
* Utility class to guarantee a mixed GC. The class allocates several arrays and
* promotes them to the oldgen. After that it tries to provoke mixed GC by
* allocating new objects.
*
* The necessary condition for guaranteed mixed GC is running MixedGCProvoker is
* running in VM with the following flags: -XX:MaxTenuringThreshold=1 -Xms12M
* -Xmx12M -XX:G1MixedGCLiveThresholdPercent=100 -XX:G1HeapWastePercent=0
* -XX:G1HeapRegionSize=1m
*/
public class MixedGCProvoker {
private final WhiteBox WB = WhiteBox.getWhiteBox();
private final List<byte[]> liveOldObjects = new ArrayList<>();
private final List<byte[]> newObjects = new ArrayList<>();
public static final int ALLOCATION_SIZE = 20000;
public static final int ALLOCATION_COUNT = 15;
public void allocateOldObjects() {
List<byte[]> deadOldObjects = new ArrayList<>();
// Allocates buffer and promotes it to the old gen. Mix live and dead old
// objects
for (int i = 0; i < ALLOCATION_COUNT; ++i) {
liveOldObjects.add(new byte[ALLOCATION_SIZE * 5]);
deadOldObjects.add(new byte[ALLOCATION_SIZE * 5]);
}
// Do two young collections, MaxTenuringThreshold=1 will force promotion.
// G1HeapRegionSize=1m guarantees that old gen regions will be filled.
WB.youngGC();
WB.youngGC();
// Check it is promoted & keep alive
Asserts.assertTrue(WB.isObjectInOldGen(liveOldObjects),
"List of the objects is suppose to be in OldGen");
Asserts.assertTrue(WB.isObjectInOldGen(deadOldObjects),
"List of the objects is suppose to be in OldGen");
}
/**
* Waits until Concurent Mark Cycle finishes
* @param wb Whitebox instance
* @param sleepTime sleep time
*/
private void waitTillCMCFinished(int sleepTime) {
while (WB.g1InConcurrentMark()) {
if (sleepTime > -1) {
try {
Thread.sleep(sleepTime);
} catch (InterruptedException e) {
System.out.println("Got InterruptedException while waiting for ConcMarkCycle to finish");
}
}
}
}
public void provokeMixedGC() {
waitTillCMCFinished(0);
WB.g1StartConcMarkCycle();
waitTillCMCFinished(0);
WB.youngGC();
System.out.println("Allocating new objects to provoke mixed GC");
// Provoke a mixed collection. G1MixedGCLiveThresholdPercent=100
// guarantees that full old gen regions will be included.
for (int i = 0; i < (ALLOCATION_COUNT * 20); i++) {
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),
"List of the objects is suppose to be in OldGen");
}
}
}

View File

@ -0,0 +1,102 @@
/*
* Copyright (c) 2020, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*/
package gc.testlibrary.g1;
import static java.util.stream.IntStream.range;
import static jdk.test.lib.Asserts.assertTrue;
import static sun.hotspot.WhiteBox.getWhiteBox;
import java.util.ArrayList;
import java.util.List;
import gc.testlibrary.Helpers;
import jdk.test.lib.Asserts;
/**
* Utility class to reliably provoke a mixed GC. The class allocates several arrays and
* promotes them to the old generation. All GCs are triggered by Whitebox to ensure that they occur.
* Must use G1.
*/
public class MixedGCProvoker {
/**
* Allocate a few objects that are supposed to end up in the old generation as they are held live by the
* given array. Caller must make sure by running this test with e.g. -XX:+AlwaysTenure that the objects
* to actually be tenured.
* Mixes live and dead objects, allocating about two regions worth of objects.
* @param liveOldObjects Array receiving the live objects after this method.
* @param g1HeapRegionSize Size of a G1 heap region.
* @param arraySize Size of the byte arrays to use.
*/
public static void allocateOldObjects(
List<byte[]> liveOldObjects,
int g1HeapRegionSize,
int arraySize) {
var toUnreachable = new ArrayList<byte[]>();
// Allocates buffer and promotes it to the old gen. Mix live and dead old objects.
// allocate about two regions of old memory. At least one full old region will guarantee
// mixed collection in the future
range(0, g1HeapRegionSize/arraySize).forEach(n -> {
liveOldObjects.add(new byte[arraySize]);
toUnreachable.add(new byte[arraySize]);
});
// Do one young collection, AlwaysTenure will force promotion.
getWhiteBox().youngGC();
// Check it is promoted & keep alive
Asserts.assertTrue(getWhiteBox().isObjectInOldGen(liveOldObjects), "List of the objects is suppose to be in OldGen");
Asserts.assertTrue(getWhiteBox().isObjectInOldGen(toUnreachable), "List of the objects is suppose to be in OldGen");
}
/**
* Provoke at least one mixed gc by starting a marking cycle, waiting for its end and triggering two GCs.
* @param liveOldObjects The objects supposed to survive this marking cycle.
*/
public static void provokeMixedGC(List<byte[]> liveOldObjects) {
Helpers.waitTillCMCFinished(getWhiteBox(), 10);
getWhiteBox().g1StartConcMarkCycle();
Helpers.waitTillCMCFinished(getWhiteBox(), 10);
getWhiteBox().youngGC(); // the "Prepare Mixed" gc
getWhiteBox().youngGC(); // the "Mixed" gc
// check that liveOldObjects still alive
assertTrue(getWhiteBox().isObjectInOldGen(liveOldObjects), "List of the objects is suppose to be in OldGen");
}
/**
* Provoke a mixed GC on a G1 heap with the given heap region size.
* @param g1HeapRegionSize The size of your regions in bytes
*/
public static void allocateAndProvokeMixedGC(int g1HeapRegionSize) {
final var arraySize = 20_000;
var liveOldObjects = new ArrayList<byte[]>();
getWhiteBox().fullGC(); // Make sure the heap is in a known state.
allocateOldObjects(liveOldObjects, g1HeapRegionSize, arraySize);
provokeMixedGC(liveOldObjects);
}
}

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2018, 2019, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2018, 2020, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -32,7 +32,6 @@ import static java.util.stream.Collectors.joining;
import static java.util.stream.Collectors.toList;
import static java.util.stream.Collectors.toSet;
import static java.util.stream.IntStream.range;
import static jdk.jfr.event.gc.collection.Provoker.provokeMixedGC;
import static jdk.test.lib.Asserts.assertEquals;
import static jdk.test.lib.Asserts.assertTrue;
import static jdk.test.lib.jfr.Events.fromRecording;
@ -46,6 +45,7 @@ import java.util.Collection;
import java.util.List;
import java.util.Set;
import gc.testlibrary.g1.MixedGCProvoker;
import jdk.jfr.Recording;
import jdk.test.lib.Asserts;
import jdk.test.lib.jfr.EventNames;
@ -56,7 +56,7 @@ import sun.hotspot.WhiteBox;
* @key jfr
* @requires vm.hasJFR
* @requires vm.gc == "G1" | vm.gc == null
* @library /test/lib /test/jdk
* @library /test/lib /test/jdk /test/hotspot/jtreg
* @build sun.hotspot.WhiteBox
* @run main ClassFileInstaller sun.hotspot.WhiteBox
* @run main/othervm -XX:+UnlockExperimentalVMOptions -XX:+AlwaysTenure
@ -81,7 +81,7 @@ public class TestG1ParallelPhases {
.collect(toList()); // force evaluation of lazy stream (all weak refs must be created)
final var MEG = 1024 * 1024;
provokeMixedGC(1 * MEG);
MixedGCProvoker.allocateAndProvokeMixedGC(MEG);
recording.stop();
Set<String> usedPhases = fromRecording(recording).stream()
@ -131,64 +131,3 @@ public class TestG1ParallelPhases {
+ ", Not expected phases: " + usedPhases.stream().filter(p -> !allPhases.contains(p)).collect(joining(", ")));
}
}
/**
* Utility class to guarantee a mixed GC. The class allocates several arrays and
* promotes them to the oldgen. After that it tries to provoke mixed GC by
* allocating new objects.
*/
class Provoker {
private static void allocateOldObjects(
List<byte[]> liveOldObjects,
int g1HeapRegionSize,
int arraySize) {
var toUnreachable = new ArrayList<byte[]>();
// Allocates buffer and promotes it to the old gen. Mix live and dead old objects.
// allocate about two regions of old memory. At least one full old region will guarantee
// mixed collection in the future
range(0, g1HeapRegionSize/arraySize).forEach(n -> {
liveOldObjects.add(new byte[arraySize]);
toUnreachable.add(new byte[arraySize]);
});
// Do one young collection, AlwaysTenure will force promotion.
getWhiteBox().youngGC();
// Check it is promoted & keep alive
Asserts.assertTrue(getWhiteBox().isObjectInOldGen(liveOldObjects), "List of the objects is suppose to be in OldGen");
Asserts.assertTrue(getWhiteBox().isObjectInOldGen(toUnreachable), "List of the objects is suppose to be in OldGen");
}
private static void waitTillCMCFinished(int sleepTime) {
while (getWhiteBox().g1InConcurrentMark()) {
try {sleep(sleepTime);} catch (Exception e) {}
}
}
/**
* The necessary condition for guaranteed mixed GC is running in VM with the following flags:
* -XX:+UnlockExperimentalVMOptions -XX:+AlwaysTenure -Xms{HEAP_SIZE}M
* -Xmx{HEAP_SIZE}M -XX:G1MixedGCLiveThresholdPercent=100 -XX:G1HeapWastePercent=0
* -XX:G1HeapRegionSize={REGION_SIZE}m
*
* @param g1HeapRegionSize The size of your regions in bytes
*/
public static void provokeMixedGC(int g1HeapRegionSize) {
final var arraySize = 20_000;
var liveOldObjects = new ArrayList<byte[]>();
// Make sure the heap is in a known state.
getWhiteBox().fullGC();
allocateOldObjects(liveOldObjects, g1HeapRegionSize, arraySize);
waitTillCMCFinished(10);
getWhiteBox().g1StartConcMarkCycle();
waitTillCMCFinished(10);
getWhiteBox().youngGC();
getWhiteBox().youngGC();
// check that liveOldObjects still alive
assertTrue(getWhiteBox().isObjectInOldGen(liveOldObjects), "List of the objects is suppose to be in OldGen");
}
}