/* * Copyright (c) 2015, 2019, 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.logging; /* * @test TestPrintReferences * @bug 8136991 8186402 8186465 8188245 * @summary Validate the reference processing logging * @key gc * @library /test/lib * @modules java.base/jdk.internal.misc * java.management * @run main gc.logging.TestPrintReferences */ import java.lang.ref.SoftReference; import java.math.BigDecimal; import jdk.test.lib.process.OutputAnalyzer; import jdk.test.lib.process.ProcessTools; import java.util.regex.Pattern; import java.util.regex.Matcher; 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 phaseReconsiderSoftReferences = "Reconsider SoftReferences"; static final String phaseNotifySoftWeakReferences = "Notify Soft/WeakReferences"; static final String phaseNotifyKeepAliveFinalizer = "Notify and keep alive finalizable"; static final String phaseNotifyPhantomReferences = "Notify PhantomReferences"; static final String phase1 = "Phase1"; static final String phase2 = "Phase2"; static final String phase3 = "Phase3"; static final String gcLogTimeRegex = ".* GC\\([0-9]+\\) "; public static void main(String[] args) throws Exception { testPhases(true); testPhases(false); testRefs(); } static String indent(int count) { return " {" + count + "}"; } public static void testRefs() throws Exception { ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+ref+phases=debug", "-XX:+UseG1GC", "-Xmx32M", GCTest.class.getName()); OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start()); checkRefsLogFormat(output); output.shouldHaveExitValue(0); } private static String refRegex(String reftype) { String countRegex = "[0-9]+"; return gcLogTimeRegex + indent(6) + reftype + ":\n" + gcLogTimeRegex + indent(8) + "Discovered: " + countRegex + "\n" + gcLogTimeRegex + indent(8) + "Cleared: " + countRegex + "\n"; } private static void checkRefsLogFormat(OutputAnalyzer output) { output.shouldMatch(refRegex("SoftReference") + refRegex("WeakReference") + refRegex("FinalReference") + refRegex("PhantomReference")); } public static void testPhases(boolean parallelRefProcEnabled) throws Exception { ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+phases+ref=debug", "-XX:+UseG1GC", "-Xmx32M", "-XX:" + (parallelRefProcEnabled ? "+" : "-") + "ParallelRefProcEnabled", "-XX:-UseDynamicNumberOfGCThreads", "-XX:ParallelGCThreads=2", GCTest.class.getName()); OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start()); checkLogFormat(output, parallelRefProcEnabled); checkLogValue(output); output.shouldHaveExitValue(0); } private static String phaseRegex(String phaseName) { final String timeRegex = doubleRegex + "ms"; return indent(6) + phaseName + ": " + timeRegex + "\n"; } private static String subphaseRegex(String subphaseName, boolean parallelRefProcEnabled) { final String timeRegex = "\\s+" + doubleRegex; if (parallelRefProcEnabled) { final String timeInParRegex = timeRegex +",\\s"; return gcLogTimeRegex + indent(8) + subphaseName + " \\(ms\\):\\s+(Min:" + timeInParRegex + "Avg:" + timeInParRegex + "Max:" + timeInParRegex + "Diff:" + timeInParRegex + "Sum:" + timeInParRegex + "Workers: [0-9]+|skipped)" + "\n"; } else { return gcLogTimeRegex + indent(8) + subphaseName + ":(" + timeRegex + "ms|\\s+skipped)\n"; } } // Find the first Reference Processing log and check its format. private static void checkLogFormat(OutputAnalyzer output, boolean parallelRefProcEnabled) { String timeRegex = doubleRegex + "ms"; /* Total Reference processing time */ String totalRegex = gcLogTimeRegex + indent(4) + referenceProcessing + ": " + timeRegex + "\n"; String balanceRegex = parallelRefProcEnabled ? "(" + gcLogTimeRegex + indent(8) + "Balance queues: " + timeRegex + "\n)??" : ""; final boolean p = parallelRefProcEnabled; String phase1Regex = gcLogTimeRegex + phaseRegex(phaseReconsiderSoftReferences) + balanceRegex + subphaseRegex("SoftRef", p); String phase2Regex = gcLogTimeRegex + phaseRegex(phaseNotifySoftWeakReferences) + balanceRegex + subphaseRegex("SoftRef", p) + subphaseRegex("WeakRef", p) + subphaseRegex("FinalRef", p) + subphaseRegex("Total", p); String phase3Regex = gcLogTimeRegex + phaseRegex(phaseNotifyKeepAliveFinalizer) + balanceRegex + subphaseRegex("FinalRef", p); String phase4Regex = gcLogTimeRegex + phaseRegex(phaseNotifyPhantomReferences) + balanceRegex + subphaseRegex("PhantomRef", p); output.shouldMatch(totalRegex + phase1Regex + phase2Regex + phase3Regex + phase4Regex); } // After getting time value, update 'output' for next use. private static BigDecimal getTimeValue(String name, int indentCount) { // Pattern of 'name', 'value' and some extra strings. String patternString = gcLogTimeRegex + indent(indentCount) + name + ": " + "(" + doubleRegex + ")"; Matcher m = Pattern.compile(patternString).matcher(output); if (!m.find()) { throw new RuntimeException("Could not find time log for " + patternString); } String match = m.group(); String value = m.group(1); double result = Double.parseDouble(value); int index = output.indexOf(match); if (index != -1) { output = output.substring(index, output.length()); } // Convert to BigDecimal to control the precision of floating point arithmetic. return BigDecimal.valueOf(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. // Because of this we need method to verify that our measurements and calculations are valid. private static boolean greaterThanOrApproximatelyEqual(BigDecimal phaseTime, BigDecimal sumOfSubPhasesTime, BigDecimal tolerance) { if (phaseTime.compareTo(sumOfSubPhasesTime) >= 0) { // phaseTime is greater than or equal. return true; } BigDecimal diff = sumOfSubPhasesTime.subtract(phaseTime); if (diff.compareTo(tolerance) <= 0) { // Difference is within tolerance, so approximately equal. return true; } // sumOfSubPhasesTime is greater than phaseTime and not within tolerance. return false; } // Find the first concurrent Reference Processing log and compare phase time vs. sum of sub-phases. public static void checkLogValue(OutputAnalyzer out) { output = out.getStdout(); String patternString = gcLogTimeRegex + indent(0) + referenceProcessing + ": " + "[0-9]+[.,][0-9]+"; Matcher m = Pattern.compile(patternString).matcher(output); if (m.find()) { int start = m.start(); int end = output.length(); // If there's another concurrent Reference Processing log, ignore it. if (m.find()) { end = m.start(); } if (start != -1) { output = output.substring(start, end); checkTrimmedLogValue(); } } } private static void checkTrimmedLogValue() { BigDecimal refProcTime = getTimeValue(referenceProcessing, 0); BigDecimal sumOfSubPhasesTime = getTimeValue(phaseReconsiderSoftReferences, 2); sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifySoftWeakReferences, 2)); sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifyKeepAliveFinalizer, 2)); sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifyPhantomReferences, 2)); // If there are 4 phases, we should allow 0.2 tolerance. final BigDecimal toleranceFor4SubPhases = BigDecimal.valueOf(0.2); if (!greaterThanOrApproximatelyEqual(refProcTime, sumOfSubPhasesTime, toleranceFor4SubPhases)) { throw new RuntimeException("Reference Processing time(" + refProcTime + "ms) is less than the sum(" + sumOfSubPhasesTime + "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()); } } } }