1 /* 2 * Copyright (c) 2015, 2017, 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 /* 25 * @test TestPrintReferences 26 * @bug 8136991 8186402 8186465 8188245 27 * @summary Validate the reference processing logging 28 * @key gc 29 * @library /test/lib 30 * @modules java.base/jdk.internal.misc 31 * java.management 32 */ 33 34 import java.lang.ref.SoftReference; 35 import java.math.BigDecimal; 36 import java.util.ArrayList; 37 38 import jdk.test.lib.process.OutputAnalyzer; 39 import jdk.test.lib.process.ProcessTools; 40 import java.util.regex.Pattern; 41 import java.util.regex.Matcher; 42 43 public class TestPrintReferences { 44 static String output; 45 static final String doubleRegex = "[0-9]+[.,][0-9]+"; 46 static final String referenceProcessing = "Reference Processing"; 47 static final String softReference = "SoftReference"; 48 static final String weakReference = "WeakReference"; 49 static final String finalReference = "FinalReference"; 50 static final String phantomReference = "PhantomReference"; 51 static final String phase1 = "Phase1"; 52 static final String phase2 = "Phase2"; 53 static final String phase3 = "Phase3"; 54 static final String gcLogTimeRegex = ".* GC\\([0-9]+\\) "; 55 56 public static void main(String[] args) throws Exception { 57 test(true); 58 test(false); 59 } 60 61 static String indent(int count) { 62 return " {" + count + "}"; 63 } 64 65 public static void test(boolean parallelRefProcEnabled) throws Exception { 66 ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+phases+ref=debug", 67 "-XX:+UseG1GC", 68 "-Xmx32M", 69 // Explicit thread setting is required to avoid using only 1 thread 70 "-XX:" + (parallelRefProcEnabled ? "+" : "-") + "ParallelRefProcEnabled", 71 "-XX:ParallelGCThreads=2", 72 GCTest.class.getName()); 73 OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start()); 74 75 checkLogFormat(output, parallelRefProcEnabled); 76 checkLogValue(output); 77 78 output.shouldHaveExitValue(0); 79 } 80 81 // Find the first Reference Processing log and check its format. 82 public static void checkLogFormat(OutputAnalyzer output, boolean parallelRefProcEnabled) { 83 String countRegex = "[0-9]+"; 84 String timeRegex = doubleRegex + "ms"; 85 String totalRegex = gcLogTimeRegex + indent(4) + referenceProcessing + ": " + timeRegex + "\n"; 86 String balanceRegex = parallelRefProcEnabled ? gcLogTimeRegex + indent(8) + "Balance queues: " + timeRegex + "\n" : ""; 87 String softRefRegex = gcLogTimeRegex + indent(6) + softReference + ": " + timeRegex + "\n"; 88 String weakRefRegex = gcLogTimeRegex + indent(6) + weakReference + ": " + timeRegex + "\n"; 89 String finalRefRegex = gcLogTimeRegex + indent(6) + finalReference + ": " + timeRegex + "\n"; 90 String phantomRefRegex = gcLogTimeRegex + indent(6) + phantomReference + ": " + timeRegex + "\n"; 91 String refDetailRegex = gcLogTimeRegex + indent(8) + phase2 + ": " + timeRegex + "\n" + 92 gcLogTimeRegex + indent(8) + phase3 + ": " + timeRegex + "\n" + 93 gcLogTimeRegex + indent(8) + "Discovered: " + countRegex + "\n" + 94 gcLogTimeRegex + indent(8) + "Cleared: " + countRegex + "\n"; 95 String softRefDetailRegex = gcLogTimeRegex + indent(8) + phase1 + ": " + timeRegex + "\n" + refDetailRegex; 96 String enqueueRegex = gcLogTimeRegex + indent(4) + "Reference Enqueuing: " + timeRegex + "\n"; 97 String enqueueDetailRegex = gcLogTimeRegex + indent(6) + "Reference Counts: Soft: " + countRegex + 98 " Weak: " + countRegex + " Final: " + countRegex + " Phantom: " + countRegex + "\n"; 99 100 output.shouldMatch(/* Total Reference processing time */ 101 totalRegex + 102 /* SoftReference processing */ 103 softRefRegex + balanceRegex + softRefDetailRegex + 104 /* WeakReference processing */ 105 weakRefRegex + balanceRegex + refDetailRegex + 106 /* FinalReference processing */ 107 finalRefRegex + balanceRegex + refDetailRegex + 108 /* PhantomReference processing */ 109 phantomRefRegex + balanceRegex + refDetailRegex + 110 /* Total Enqueuing time */ 111 enqueueRegex + 112 /* Enqueued Stats */ 113 enqueueDetailRegex 114 ); 115 } 116 117 // After getting time value, update 'output' for next use. 118 public static BigDecimal getTimeValue(String name, int indentCount) { 119 // Pattern of 'name', 'value' and some extra strings. 120 String patternString = gcLogTimeRegex + indent(indentCount) + name + ": " + "(" + doubleRegex + ")"; 121 Matcher m = Pattern.compile(patternString).matcher(output); 122 if (!m.find()) { 123 throw new RuntimeException("Could not find time log for " + patternString); 124 } 125 126 String match = m.group(); 127 String value = m.group(1); 128 129 double result = Double.parseDouble(value); 130 131 int index = output.indexOf(match); 132 if (index != -1) { 133 output = output.substring(index, output.length()); 134 } 135 136 // Convert to BigDecimal to control the precision of floating point arithmetic. 137 return BigDecimal.valueOf(result); 138 } 139 140 // Reference log is printing 1 decimal place of elapsed time. 141 // So sum of each sub-phases could be slightly larger than the enclosing phase in some cases. 142 // e.g. If there are 3 sub-phases: 143 // Actual value: SoftReference(5.55) = phase1(1.85) + phase2(1.85) + phase3(1.85) 144 // Log value: SoftReference(5.6) = phase1(1.9) + phase2(1.9) + phase3(1.9) 145 // When checked: 5.6 < 5.7 (sum of phase1~3) 146 // Because of this we need method to verify that our measurements and calculations are valid. 147 public static boolean greaterThanOrApproximatelyEqual(BigDecimal phaseTime, BigDecimal sumOfSubPhasesTime, BigDecimal tolerance) { 148 if (phaseTime.compareTo(sumOfSubPhasesTime) >= 0) { 149 // phaseTime is greater than or equal. 150 return true; 151 } 152 153 BigDecimal diff = sumOfSubPhasesTime.subtract(phaseTime); 154 if (diff.compareTo(tolerance) <= 0) { 155 // Difference is within tolerance, so approximately equal. 156 return true; 157 } 158 159 // sumOfSubPhasesTime is greater than phaseTime and not within tolerance. 160 return false; 161 } 162 163 public static BigDecimal checkPhaseTime(String refType) { 164 BigDecimal phaseTime = getTimeValue(refType, 2); 165 BigDecimal sumOfSubPhasesTime = BigDecimal.valueOf(0.0); 166 167 if (softReference.equals(refType)) { 168 sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phase1, 4)); 169 } 170 sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phase2, 4)); 171 sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phase3, 4)); 172 173 // If there are 3 sub-phases, we should allow 0.1 tolerance. 174 final BigDecimal toleranceFor3SubPhases = BigDecimal.valueOf(0.1); 175 if (!greaterThanOrApproximatelyEqual(phaseTime, sumOfSubPhasesTime, toleranceFor3SubPhases)) { 176 throw new RuntimeException(refType +" time(" + phaseTime + 177 "ms) is less than the sum(" + sumOfSubPhasesTime + "ms) of each phases"); 178 } 179 180 return phaseTime; 181 } 182 183 // Find the first concurrent Reference Processing log and compare phase time vs. sum of sub-phases. 184 public static void checkLogValue(OutputAnalyzer out) { 185 output = out.getStdout(); 186 187 BigDecimal refProcTime = getTimeValue(referenceProcessing, 0); 188 189 BigDecimal sumOfSubPhasesTime = checkPhaseTime(softReference); 190 sumOfSubPhasesTime = sumOfSubPhasesTime.add(checkPhaseTime(weakReference)); 191 sumOfSubPhasesTime = sumOfSubPhasesTime.add(checkPhaseTime(finalReference)); 192 sumOfSubPhasesTime = sumOfSubPhasesTime.add(checkPhaseTime(phantomReference)); 193 194 // If there are 4 sub-phases, we should allow 0.2 tolerance. 195 final BigDecimal toleranceFor4SubPhases = BigDecimal.valueOf(0.2); 196 if (!greaterThanOrApproximatelyEqual(refProcTime, sumOfSubPhasesTime, toleranceFor4SubPhases)) { 197 throw new RuntimeException("Reference Processing time(" + refProcTime + "ms) is less than the sum(" 198 + sumOfSubPhasesTime + "ms) of each phases"); 199 } 200 } 201 202 static class GCTest { 203 static final int SIZE = 512 * 1024; 204 static Object[] dummy = new Object[SIZE]; 205 206 public static void main(String [] args) { 207 for (int i = 0; i < SIZE; i++) { 208 dummy[i] = new SoftReference<>(new Object()); 209 } 210 } 211 } 212 }