Skip to content

/ loom

Permalink
Browse files

8237079: gc/g1/mixedgc/TestLogging.java fails with "Pause Young (Mixe… 

…d) (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
  • Loading branch information
Thomas Schatzl
Thomas Schatzl committed Jan 23, 2020
1 parent da7ceba commit ffcc58260191dd8dc3428db98c49e0bca55133eb
123 test/hotspot/jtreg/gc/g1/mixedgc/TestLogging.java
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,30 +21,29 @@
* 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
* @run driver ClassFileInstaller sun.hotspot.WhiteBox
* @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,32 +54,28 @@
"-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",
"-XX:MaxGCPauseMillis=30000", // to have enough time
"-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 {
System.out.println(String.format("%s: running with %s flag", TestLogging.class.getSimpleName(), vmFlag));
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,90 +88,18 @@ private static OutputAnalyzer spawnMixedGCProvoker(String... extraFlags)
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()]));
return new OutputAnalyzer(pb.start());
}
}

/**
* 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);
}
}

132 test/hotspot/jtreg/gc/g1/mixedgc/TestOldGenCollectionUsage.java
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 void run() {
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 void run() {
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 void run() {

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");
}

}

}

0 comments on commit ffcc582

Please sign in to comment.