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 }