--- old/test/gc/logging/TestPrintReferences.java 2017-08-24 21:22:14.663708312 -0700 +++ new/test/gc/logging/TestPrintReferences.java 2017-08-24 21:22:14.543708316 -0700 @@ -51,6 +51,7 @@ 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 { @@ -114,7 +115,13 @@ } String match = m.group(); - double result = Double.parseDouble(match.substring(match.lastIndexOf(" ") + 1, match.length())); + + // 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) { @@ -124,8 +131,24 @@ return result; } + // 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; + + 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)); + } + public static double checkRefTime(String refType) { - String indent_2 = " "; double refTime = getTimeValue(gcLogTimeRegex + indent_2 + refType); double total = 0.0; @@ -135,7 +158,7 @@ total += getTimeValue(gcLogTimeRegex + indent_4 + phase2); total += getTimeValue(gcLogTimeRegex + indent_4 + phase3); - if (refTime < total) { + 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"); } @@ -146,7 +169,7 @@ // Find the first concurrent Reference Processing log and compare sub-time vs. total. public static void checkLogValue(OutputAnalyzer out) { output = out.getStdout(); - System.out.println(output); + double refProcTime = getTimeValue(gcLogTimeRegex + referenceProcessing); double total = 0.0; @@ -155,18 +178,18 @@ total += checkRefTime(finalReference); total += checkRefTime(phantomReference); - if (refProcTime < total) { + 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 M = 512 * 1024; - static Object[] dummy = new Object[M]; + static final int SIZE = 512 * 1024; + static Object[] dummy = new Object[SIZE]; public static void main(String [] args) { - for (int i = 0; i < M; i++) { + for (int i = 0; i < SIZE; i++) { dummy[i] = new SoftReference<>(new Object()); } }