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 }