1 /* 2 * Copyright (c) 2015, 2019, Oracle and/or its affiliates. All rights reserved. 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 4 * 5 * This code is free software; you can redistribute it and/or modify it 6 * under the terms of the GNU General Public License version 2 only, as 7 * published by the Free Software Foundation. 8 * 9 * This code is distributed in the hope that it will be useful, but WITHOUT 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 12 * version 2 for more details (a copy is included in the LICENSE file that 13 * accompanied this code). 14 * 15 * You should have received a copy of the GNU General Public License version 16 * 2 along with this work; if not, write to the Free Software Foundation, 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 18 * 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 20 * or visit www.oracle.com if you need additional information or have any 21 * questions. 22 */ 23 24 package gc.logging; 25 26 /* 27 * @test TestPrintReferences 28 * @bug 8136991 8186402 8186465 8188245 29 * @summary Validate the reference processing logging 30 * @key gc 31 * @library /test/lib 32 * @modules java.base/jdk.internal.misc 33 * java.management 34 * @run main gc.logging.TestPrintReferences 35 */ 36 37 import java.lang.ref.SoftReference; 38 import java.math.BigDecimal; 39 import jdk.test.lib.process.OutputAnalyzer; 40 import jdk.test.lib.process.ProcessTools; 41 import java.util.regex.Pattern; 42 import java.util.regex.Matcher; 43 44 public class TestPrintReferences { 45 static String output; 46 static final String doubleRegex = "[0-9]+[.,][0-9]+"; 47 static final String referenceProcessing = "Reference Processing"; 48 static final String softReference = "SoftReference"; 49 static final String weakReference = "WeakReference"; 50 static final String finalReference = "FinalReference"; 51 static final String phantomReference = "PhantomReference"; 52 53 static final String phaseReconsiderSoftReferences = "Reconsider SoftReferences"; 54 static final String phaseNotifySoftWeakReferences = "Notify Soft/WeakReferences"; 55 static final String phaseNotifyKeepAliveFinalizer = "Notify and keep alive finalizable"; 56 static final String phaseNotifyPhantomReferences = "Notify PhantomReferences"; 57 58 static final String phase1 = "Phase1"; 59 static final String phase2 = "Phase2"; 60 static final String phase3 = "Phase3"; 61 static final String gcLogTimeRegex = ".* GC\\([0-9]+\\) "; 62 63 public static void main(String[] args) throws Exception { 64 testPhases(true); 65 testPhases(false); 66 testRefs(); 67 } 68 69 static String indent(int count) { 70 return " {" + count + "}"; 71 } 72 73 public static void testRefs() throws Exception { 74 ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+ref+phases=debug", 75 "-XX:+UseG1GC", 76 "-Xmx32M", 77 GCTest.class.getName()); 78 OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start()); 79 80 checkRefsLogFormat(output); 81 82 output.shouldHaveExitValue(0); 83 } 84 85 private static String refRegex(String reftype) { 86 String countRegex = "[0-9]+"; 87 return gcLogTimeRegex + indent(6) + reftype + ":\n" + 88 gcLogTimeRegex + indent(8) + "Discovered: " + countRegex + "\n" + 89 gcLogTimeRegex + indent(8) + "Cleared: " + countRegex + "\n"; 90 } 91 92 private static void checkRefsLogFormat(OutputAnalyzer output) { 93 output.shouldMatch(refRegex("SoftReference") + 94 refRegex("WeakReference") + 95 refRegex("FinalReference") + 96 refRegex("PhantomReference")); 97 } 98 99 public static void testPhases(boolean parallelRefProcEnabled) throws Exception { 100 ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+phases+ref=debug", 101 "-XX:+UseG1GC", 102 "-Xmx32M", 103 "-XX:" + (parallelRefProcEnabled ? "+" : "-") + "ParallelRefProcEnabled", 104 "-XX:-UseDynamicNumberOfGCThreads", 105 "-XX:ParallelGCThreads=2", 106 GCTest.class.getName()); 107 OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start()); 108 109 checkLogFormat(output, parallelRefProcEnabled); 110 checkLogValue(output); 111 112 output.shouldHaveExitValue(0); 113 } 114 115 private static String phaseRegex(String phaseName) { 116 final String timeRegex = doubleRegex + "ms"; 117 return indent(6) + phaseName + ": " + timeRegex + "\n"; 118 } 119 120 private static String subphaseRegex(String subphaseName, boolean parallelRefProcEnabled) { 121 final String timeRegex = "\\s+" + doubleRegex; 122 if (parallelRefProcEnabled) { 123 final String timeInParRegex = timeRegex +",\\s"; 124 return gcLogTimeRegex + indent(8) + subphaseName + 125 " \\(ms\\):\\s+(Min:" + timeInParRegex + "Avg:" + timeInParRegex + "Max:" + timeInParRegex + "Diff:" + timeInParRegex + "Sum:" + timeInParRegex + 126 "Workers: [0-9]+|skipped)" + "\n"; 127 } else { 128 return gcLogTimeRegex + indent(8) + subphaseName + ":(" + timeRegex + "ms|\\s+skipped)\n"; 129 } 130 } 131 132 // Find the first Reference Processing log and check its format. 133 private static void checkLogFormat(OutputAnalyzer output, boolean parallelRefProcEnabled) { 134 String timeRegex = doubleRegex + "ms"; 135 136 /* Total Reference processing time */ 137 String totalRegex = gcLogTimeRegex + indent(4) + referenceProcessing + ": " + timeRegex + "\n"; 138 139 String balanceRegex = parallelRefProcEnabled ? "(" + gcLogTimeRegex + indent(8) + "Balance queues: " + timeRegex + "\n)??" : ""; 140 141 final boolean p = parallelRefProcEnabled; 142 143 String phase1Regex = gcLogTimeRegex + phaseRegex(phaseReconsiderSoftReferences) + balanceRegex + subphaseRegex("SoftRef", p); 144 String phase2Regex = gcLogTimeRegex + phaseRegex(phaseNotifySoftWeakReferences) + 145 balanceRegex + 146 subphaseRegex("SoftRef", p) + 147 subphaseRegex("WeakRef", p) + 148 subphaseRegex("FinalRef", p) + 149 subphaseRegex("Total", p); 150 String phase3Regex = gcLogTimeRegex + phaseRegex(phaseNotifyKeepAliveFinalizer) + balanceRegex + subphaseRegex("FinalRef", p); 151 String phase4Regex = gcLogTimeRegex + phaseRegex(phaseNotifyPhantomReferences) + balanceRegex + subphaseRegex("PhantomRef", p); 152 153 output.shouldMatch(totalRegex + 154 phase1Regex + 155 phase2Regex + 156 phase3Regex + 157 phase4Regex); 158 } 159 160 // After getting time value, update 'output' for next use. 161 private static BigDecimal getTimeValue(String name, int indentCount) { 162 // Pattern of 'name', 'value' and some extra strings. 163 String patternString = gcLogTimeRegex + indent(indentCount) + name + ": " + "(" + doubleRegex + ")"; 164 Matcher m = Pattern.compile(patternString).matcher(output); 165 if (!m.find()) { 166 throw new RuntimeException("Could not find time log for " + patternString); 167 } 168 169 String match = m.group(); 170 String value = m.group(1); 171 172 double result = Double.parseDouble(value); 173 174 int index = output.indexOf(match); 175 if (index != -1) { 176 output = output.substring(index, output.length()); 177 } 178 179 // Convert to BigDecimal to control the precision of floating point arithmetic. 180 return BigDecimal.valueOf(result); 181 } 182 183 // Reference log is printing 1 decimal place of elapsed time. 184 // So sum of each sub-phases could be slightly larger than the enclosing phase in some cases. 185 // Because of this we need method to verify that our measurements and calculations are valid. 186 private static boolean greaterThanOrApproximatelyEqual(BigDecimal phaseTime, BigDecimal sumOfSubPhasesTime, BigDecimal tolerance) { 187 if (phaseTime.compareTo(sumOfSubPhasesTime) >= 0) { 188 // phaseTime is greater than or equal. 189 return true; 190 } 191 192 BigDecimal diff = sumOfSubPhasesTime.subtract(phaseTime); 193 if (diff.compareTo(tolerance) <= 0) { 194 // Difference is within tolerance, so approximately equal. 195 return true; 196 } 197 198 // sumOfSubPhasesTime is greater than phaseTime and not within tolerance. 199 return false; 200 } 201 202 // Find the first concurrent Reference Processing log and compare phase time vs. sum of sub-phases. 203 public static void checkLogValue(OutputAnalyzer out) { 204 output = out.getStdout(); 205 206 String patternString = gcLogTimeRegex + indent(0) + 207 referenceProcessing + ": " + "[0-9]+[.,][0-9]+"; 208 Matcher m = Pattern.compile(patternString).matcher(output); 209 if (m.find()) { 210 int start = m.start(); 211 int end = output.length(); 212 // If there's another concurrent Reference Processing log, ignore it. 213 if (m.find()) { 214 end = m.start(); 215 } 216 if (start != -1) { 217 output = output.substring(start, end); 218 checkTrimmedLogValue(); 219 } 220 } 221 } 222 223 private static void checkTrimmedLogValue() { 224 BigDecimal refProcTime = getTimeValue(referenceProcessing, 0); 225 226 BigDecimal sumOfSubPhasesTime = getTimeValue(phaseReconsiderSoftReferences, 2); 227 sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifySoftWeakReferences, 2)); 228 sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifyKeepAliveFinalizer, 2)); 229 sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifyPhantomReferences, 2)); 230 231 // If there are 4 phases, we should allow 0.2 tolerance. 232 final BigDecimal toleranceFor4SubPhases = BigDecimal.valueOf(0.2); 233 if (!greaterThanOrApproximatelyEqual(refProcTime, sumOfSubPhasesTime, toleranceFor4SubPhases)) { 234 throw new RuntimeException("Reference Processing time(" + refProcTime + "ms) is less than the sum(" 235 + sumOfSubPhasesTime + "ms) of each phases"); 236 } 237 } 238 239 static class GCTest { 240 static final int SIZE = 512 * 1024; 241 static Object[] dummy = new Object[SIZE]; 242 243 public static void main(String [] args) { 244 for (int i = 0; i < SIZE; i++) { 245 dummy[i] = new SoftReference<>(new Object()); 246 } 247 } 248 } 249 }