--- old/test/gc/logging/TestPrintReferences.java 2017-08-24 21:21:57.195708920 -0700 +++ new/test/gc/logging/TestPrintReferences.java 2017-08-24 21:21:57.071708924 -0700 @@ -23,7 +23,7 @@ /* * @test TestPrintReferences - * @bug 8136991 8186402 + * @bug 8136991 8186402 8186465 * @summary Validate the reference processing logging * @key gc * @library /test/lib @@ -36,34 +36,56 @@ import jdk.test.lib.process.OutputAnalyzer; import jdk.test.lib.process.ProcessTools; +import java.util.*; +import java.util.regex.*; public class TestPrintReferences { + static String output; + static final String doubleRegex = "[0-9]+[.,][0-9]+"; + static final String referenceProcessing = "Reference Processing: "; + static final String softReference = "SoftReference: "; + static final String weakReference = "WeakReference: "; + static final String finalReference = "FinalReference: "; + static final String phantomReference = "PhantomReference: "; + static final String phase1 = "Phase1: "; + static final String phase2 = "Phase2: "; + static final String phase3 = "Phase3: "; + static final String gcLogTimeRegex = ".* GC\\([0-9]+\\) "; + static final String indent_2 = " "; + static final String indent_4 = " "; + public static void main(String[] args) throws Exception { ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+phases+ref=debug", "-XX:+UseG1GC", - "-Xmx10M", + "-Xmx32M", // Explicit thread setting is required to avoid using only 1 thread "-XX:ParallelGCThreads=2", GCTest.class.getName()); OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start()); - String indent_4 = " "; + checkLogFormat(output); + checkLogValue(output); + + output.shouldHaveExitValue(0); + } + + // Find the first Reference Processing log and check its format. + public static void checkLogFormat(OutputAnalyzer output) { String indent_6 = " "; String indent_8 = " "; - String gcLogTimeRegex = ".* GC\\([0-9]+\\) "; String countRegex = "[0-9]+"; - String timeRegex = "[0-9]+[.,][0-9]+ms"; - String totalRegex = gcLogTimeRegex + indent_4 + "Reference Processing: " + timeRegex + "\n"; + String timeRegex = doubleRegex + "ms"; + String totalRegex = gcLogTimeRegex + indent_4 + referenceProcessing + timeRegex + "\n"; String balanceRegex = gcLogTimeRegex + indent_8 + "Balance queues: " + timeRegex + "\n"; - String softRefRegex = gcLogTimeRegex + indent_6 + "SoftReference: " + timeRegex + "\n"; - String weakRefRegex = gcLogTimeRegex + indent_6 + "WeakReference: " + timeRegex + "\n"; - String finalRefRegex = gcLogTimeRegex + indent_6 + "FinalReference: " + timeRegex + "\n"; - String phantomRefRegex = gcLogTimeRegex + indent_6 + "PhantomReference: " + timeRegex + "\n"; - String refDetailRegex = gcLogTimeRegex + indent_8 + "Phase2: " + timeRegex + "\n" + - gcLogTimeRegex + indent_8 + "Phase3: " + timeRegex + "\n" + + String softRefRegex = gcLogTimeRegex + indent_6 + softReference + timeRegex + "\n"; + String weakRefRegex = gcLogTimeRegex + indent_6 + weakReference + timeRegex + "\n"; + String finalRefRegex = gcLogTimeRegex + indent_6 + finalReference + timeRegex + "\n"; + String phantomRefRegex = gcLogTimeRegex + indent_6 + phantomReference + timeRegex + "\n"; + String refDetailRegex = gcLogTimeRegex + indent_8 + phase2 + timeRegex + "\n" + + gcLogTimeRegex + indent_8 + phase3 + timeRegex + "\n" + gcLogTimeRegex + indent_8 + "Discovered: " + countRegex + "\n" + gcLogTimeRegex + indent_8 + "Cleared: " + countRegex + "\n"; - String softRefDetailRegex = gcLogTimeRegex + indent_8 + "Phase1: " + timeRegex + "\n" + refDetailRegex; + String softRefDetailRegex = gcLogTimeRegex + indent_8 + phase1 + timeRegex + "\n" + refDetailRegex; String enqueueRegex = gcLogTimeRegex + indent_4 + "Reference Enqueuing: " + timeRegex + "\n"; String enqueueDetailRegex = gcLogTimeRegex + indent_6 + "Reference Counts: Soft: " + countRegex + " Weak: " + countRegex + " Final: " + countRegex + " Phantom: " + countRegex + "\n"; @@ -83,22 +105,92 @@ /* Enqueued Stats */ enqueueDetailRegex ); + } - output.shouldHaveExitValue(0); + // After getting time value, update 'output' for next use. + public static double getTimeValue(String name) { + Matcher m = Pattern.compile(name + doubleRegex).matcher(output); + if (!m.find()) { + throw new RuntimeException("Could not find time log for " + name); + } + + String match = m.group(); + + // Skip the first timestamp and get elapsed time which starts with space. + m = Pattern.compile(" " + doubleRegex).matcher(match); + if (!m.find()) { + throw new RuntimeException("Could not find time log for " + doubleRegex); + } + double result = Double.parseDouble(m.group()); + + int index = output.indexOf(match); + if (index != -1) { + output = output.substring(index, output.length()); + } + + return result; } - static class GCTest { - static final int M = 1024 * 1024; + // Reference log is printing 1 decimal place of elapsed time. + // So sum of each sub-phases could be slightly larger than the enclosing phase in some cases. + // As the maximum of sub-phases is 3, allow 0.1 of TOLERANCE. + // e.g. Actual value: SoftReference(5.55) = phase1(1.85) + phase2(1.85) + phase3(1.85) + // Log value: SoftReference(5.6) = phase1(1.9) + phase2(1.9) + phase3(1.9) + // When checked: 5.6 < 5.7 (sum of phase1~3) + public static boolean approximatelyEqual(double a, double b) { + final double TOLERANCE = 0.1; - public static void main(String [] args) { + return Math.abs(a - b) <= TOLERANCE; + } + + // Return false, if 'total' is larger and not approximately equal to 'refTime'. + public static boolean compare(double refTime, double total) { + return (refTime < total) && (!approximatelyEqual(refTime, total)); + } - ArrayList arrSoftRefs = new ArrayList(); + public static double checkRefTime(String refType) { + double refTime = getTimeValue(gcLogTimeRegex + indent_2 + refType); + double total = 0.0; - // Populate to triger GC and then Reference related logs will be printed. - for (int i = 0; i < 10; i++) { - byte[] tmp = new byte[M]; + if (softReference.equals(refType)) { + total += getTimeValue(gcLogTimeRegex + indent_4 + phase1); + } + total += getTimeValue(gcLogTimeRegex + indent_4 + phase2); + total += getTimeValue(gcLogTimeRegex + indent_4 + phase3); + + if (compare(refTime, total)) { + throw new RuntimeException(refType.substring(0, refType.length()-2) +" time(" + refTime + + "ms) is less than the sum(" + total + "ms) of each phases"); + } - arrSoftRefs.add(new SoftReference(tmp)); + return refTime; + } + + // Find the first concurrent Reference Processing log and compare sub-time vs. total. + public static void checkLogValue(OutputAnalyzer out) { + output = out.getStdout(); + + double refProcTime = getTimeValue(gcLogTimeRegex + referenceProcessing); + + double total = 0.0; + total += checkRefTime(softReference); + total += checkRefTime(weakReference); + total += checkRefTime(finalReference); + total += checkRefTime(phantomReference); + + if (compare(refProcTime, total)) { + throw new RuntimeException("Reference Processing time(" + refProcTime + "ms) is less than the sum(" + + total + "ms) of each phases"); + } + } + + static class GCTest { + static final int SIZE = 512 * 1024; + static Object[] dummy = new Object[SIZE]; + + public static void main(String [] args) { + for (int i = 0; i < SIZE; i++) { + dummy[i] = new SoftReference<>(new Object()); } } }