1 /*
2 * Copyright (c) 2014, 2023, 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.g1;
25
26 /*
27 * @test TestGCLogMessages
28 * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962 8069330 8076463 8150630 8160055 8177059 8166191
29 * @summary Ensure the output for a minor GC with G1
30 * includes the expected necessary messages.
31 * @requires vm.gc.G1
32 * @library /test/lib
33 * @modules java.base/jdk.internal.misc
34 * java.management
35 * @build jdk.test.whitebox.WhiteBox
36 * @run driver jdk.test.lib.helpers.ClassFileInstaller jdk.test.whitebox.WhiteBox
37 * @run main/othervm -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI
38 * gc.g1.TestGCLogMessages
39 */
40
41 import jdk.test.lib.process.OutputAnalyzer;
42 import jdk.test.lib.Platform;
43 import jdk.test.lib.process.ProcessTools;
44 import jdk.test.whitebox.code.Compiler;
45
46 public class TestGCLogMessages {
47
48 private enum Level {
49 OFF(""),
50 INFO("info"),
51 DEBUG("debug"),
52 TRACE("trace");
53
54 private String logName;
55
56 Level(String logName) {
57 this.logName = logName;
58 }
59
60 public boolean lessThan(Level other) {
61 return this.compareTo(other) < 0;
62 }
63
64 public String toString() {
65 return logName;
66 }
67 }
68
69 private class LogMessageWithLevel {
70 String message;
71 Level level;
72
73 public LogMessageWithLevel(String message, Level level) {
74 this.message = message;
75 this.level = level;
76 }
77
78 public boolean isAvailable() {
79 return true;
80 }
81 };
82
83 private class LogMessageWithLevelC2OrJVMCIOnly extends LogMessageWithLevel {
84 public LogMessageWithLevelC2OrJVMCIOnly(String message, Level level) {
85 super(message, level);
86 }
87
88 public boolean isAvailable() {
89 return Compiler.isC2OrJVMCIIncluded();
90 }
91 }
92
93 private class LogMessageWithJFROnly extends LogMessageWithLevel {
94 public LogMessageWithJFROnly(String message, Level level) {
95 super(message, level);
96 }
97
98 public boolean isAvailable() {
99 jdk.test.whitebox.WhiteBox WB = jdk.test.whitebox.WhiteBox.getWhiteBox();
100 return WB.isJFRIncluded();
101 }
102 }
103
104 private LogMessageWithLevel allLogMessages[] = new LogMessageWithLevel[] {
105 new LogMessageWithLevel("Pre Evacuate Collection Set:", Level.INFO),
106 new LogMessageWithLevel("Evacuate Collection Set:", Level.INFO),
107 new LogMessageWithLevel("Post Evacuate Collection Set:", Level.INFO),
108 new LogMessageWithLevel("Other:", Level.INFO),
109
110 // Pre Evacuate Collection Set
111 new LogMessageWithLevel("JT Retire TLABs And Flush Logs \\(ms\\):", Level.DEBUG),
112 new LogMessageWithLevel("Non-JT Flush Logs \\(ms\\):", Level.DEBUG),
113 new LogMessageWithLevel("Choose Collection Set:", Level.DEBUG),
114 new LogMessageWithLevel("Region Register:", Level.DEBUG),
115 new LogMessageWithLevel("Prepare Heap Roots:", Level.DEBUG),
116 // Merge Heap Roots
117 new LogMessageWithLevel("Merge Heap Roots:", Level.INFO),
118 new LogMessageWithLevel("Prepare Merge Heap Roots:", Level.DEBUG),
119 new LogMessageWithLevel("Eager Reclaim \\(ms\\):", Level.DEBUG),
120 new LogMessageWithLevel("Remembered Sets \\(ms\\):", Level.DEBUG),
121 new LogMessageWithLevel("Merged Inline:", Level.DEBUG),
122 new LogMessageWithLevel("Merged ArrayOfCards:", Level.DEBUG),
123 new LogMessageWithLevel("Merged Howl:", Level.DEBUG),
124 new LogMessageWithLevel("Merged Full:", Level.DEBUG),
125 new LogMessageWithLevel("Merged Howl Inline:", Level.DEBUG),
126 new LogMessageWithLevel("Merged Howl ArrayOfCards:", Level.DEBUG),
127 new LogMessageWithLevel("Merged Howl BitMap:", Level.DEBUG),
128 new LogMessageWithLevel("Merged Howl Full:", Level.DEBUG),
129 new LogMessageWithLevel("Log Buffers \\(ms\\):", Level.DEBUG),
130 new LogMessageWithLevel("Dirty Cards:", Level.DEBUG),
131 new LogMessageWithLevel("Merged Cards:", Level.DEBUG),
132 new LogMessageWithLevel("Skipped Cards:", Level.DEBUG),
133 // Evacuate Collection Set
134 new LogMessageWithLevel("Ext Root Scanning \\(ms\\):", Level.DEBUG),
135 new LogMessageWithLevel("Thread Roots \\(ms\\):", Level.TRACE),
136 new LogMessageWithLevel("CLDG Roots \\(ms\\):", Level.TRACE),
137 new LogMessageWithLevel("CM RefProcessor Roots \\(ms\\):", Level.TRACE),
138 new LogMessageWithLevel("JNI Global Roots", Level.TRACE),
139 new LogMessageWithLevel("VM Global Roots", Level.TRACE),
140 // Scan Heap Roots
141 new LogMessageWithLevel("Scan Heap Roots \\(ms\\):", Level.DEBUG),
142 new LogMessageWithLevel("Scanned Cards:", Level.DEBUG),
143 new LogMessageWithLevel("Scanned Blocks:", Level.DEBUG),
144 new LogMessageWithLevel("Claimed Chunks:", Level.DEBUG),
145 new LogMessageWithLevel("Found Roots:", Level.DEBUG),
146 // Code Roots Scan
147 new LogMessageWithLevel("Code Root Scan \\(ms\\):", Level.DEBUG),
148 // Object Copy
149 new LogMessageWithLevel("Object Copy \\(ms\\):", Level.DEBUG),
150 new LogMessageWithLevel("Copied Bytes:", Level.DEBUG),
151 new LogMessageWithLevel("LAB Waste:", Level.DEBUG),
152 new LogMessageWithLevel("LAB Undo Waste:", Level.DEBUG),
153 // Termination
154 new LogMessageWithLevel("Termination \\(ms\\):", Level.DEBUG),
155 new LogMessageWithLevel("Termination Attempts:", Level.DEBUG),
156 // Post Evacuate Collection Set
157 // NMethod List Cleanup
158 new LogMessageWithLevel("NMethod List Cleanup:", Level.DEBUG),
159 // Reference Processing
160 new LogMessageWithLevel("Reference Processing:", Level.DEBUG),
161 // VM internal reference processing
162 new LogMessageWithLevel("Weak Processing:", Level.DEBUG),
163 new LogMessageWithLevel("VM Weak", Level.DEBUG),
164 new LogMessageWithLevel("ObjectSynchronizer Weak", Level.DEBUG),
165 new LogMessageWithLevel("JVMTI Tag Weak OopStorage", Level.DEBUG),
166 new LogMessageWithLevel("StringTable Weak", Level.DEBUG),
167 new LogMessageWithLevel("ResolvedMethodTable Weak", Level.DEBUG),
168 new LogMessageWithJFROnly("Weak JFR Old Object Samples", Level.DEBUG),
169 new LogMessageWithLevel("JNI Weak", Level.DEBUG),
170
171 // Post Evacuate Cleanup 1
172 new LogMessageWithLevel("Post Evacuate Cleanup 1:", Level.DEBUG),
173 new LogMessageWithLevel("Merge Per-Thread State \\(ms\\):", Level.DEBUG),
174 new LogMessageWithLevel("LAB Waste:", Level.DEBUG),
175 new LogMessageWithLevel("LAB Undo Waste:", Level.DEBUG),
176 new LogMessageWithLevel("Evac Fail Extra Cards:", Level.DEBUG),
177 new LogMessageWithLevel("Clear Logged Cards \\(ms\\):", Level.DEBUG),
178 new LogMessageWithLevel("Recalculate Used Memory \\(ms\\):", Level.DEBUG),
179
180 // Post Evacuate Cleanup 2
181 new LogMessageWithLevel("Post Evacuate Cleanup 2:", Level.DEBUG),
182 new LogMessageWithLevelC2OrJVMCIOnly("Update Derived Pointers", Level.DEBUG),
183 new LogMessageWithLevel("Redirty Logged Cards \\(ms\\):", Level.DEBUG),
184 new LogMessageWithLevel("Redirtied Cards:", Level.DEBUG),
185 new LogMessageWithLevel("Resize TLABs \\(ms\\):", Level.DEBUG),
186 new LogMessageWithLevel("Free Collection Set \\(ms\\):", Level.DEBUG),
187 new LogMessageWithLevel("Serial Free Collection Set:", Level.TRACE),
188 new LogMessageWithLevel("Young Free Collection Set \\(ms\\):", Level.TRACE),
189 new LogMessageWithLevel("Non-Young Free Collection Set \\(ms\\):", Level.TRACE),
190
191 // Misc Top-level
192 new LogMessageWithLevel("Rebuild Free List:", Level.DEBUG),
193 new LogMessageWithLevel("Serial Rebuild Free List:", Level.TRACE),
194 new LogMessageWithLevel("Parallel Rebuild Free List \\(ms\\):", Level.TRACE),
195 new LogMessageWithLevel("Prepare For Mutator:", Level.DEBUG),
196 new LogMessageWithLevel("Expand Heap After Collection:", Level.DEBUG),
197 };
198
199 void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception {
200 for (LogMessageWithLevel l : messages) {
201 if (level.lessThan(l.level) || !l.isAvailable()) {
202 output.shouldNotContain(l.message);
203 } else {
204 output.shouldMatch("\\[" + l.level + ".*" + l.message);
205 }
206 }
207 }
208
209 public static void main(String[] args) throws Exception {
210 new TestGCLogMessages().testNormalLogs();
211 new TestGCLogMessages().testConcurrentRefinementLogs();
212 if (Platform.isDebugBuild()) {
213 new TestGCLogMessages().testWithEvacuationFailureLogs();
214 }
215 new TestGCLogMessages().testWithConcurrentStart();
216 new TestGCLogMessages().testExpandHeap();
217 }
218
219 private void testNormalLogs() throws Exception {
220
221 OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
222 "-Xmx10M",
223 GCTest.class.getName());
224
225 checkMessagesAtLevel(output, allLogMessages, Level.OFF);
226 output.shouldHaveExitValue(0);
227
228 output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
229 "-Xmx10M",
230 "-Xlog:gc+phases=debug",
231 GCTest.class.getName());
232
233 checkMessagesAtLevel(output, allLogMessages, Level.DEBUG);
234
235 output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
236 "-Xmx10M",
237 "-Xlog:gc+phases=trace",
238 GCTest.class.getName());
239
240 checkMessagesAtLevel(output, allLogMessages, Level.TRACE);
241 output.shouldHaveExitValue(0);
242 }
243
244 LogMessageWithLevel concRefineMessages[] = new LogMessageWithLevel[] {
245 new LogMessageWithLevel("Mutator refinement: ", Level.DEBUG),
246 new LogMessageWithLevel("Concurrent refinement: ", Level.DEBUG),
247 new LogMessageWithLevel("Total refinement: ", Level.DEBUG),
248 // "Concurrent refinement rate" optionally printed if any.
249 // "Generate dirty cards rate" optionally printed if any.
250 };
251
252 private void testConcurrentRefinementLogs() throws Exception {
253 OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
254 "-Xmx10M",
255 "-Xlog:gc+refine+stats=debug",
256 GCTest.class.getName());
257 checkMessagesAtLevel(output, concRefineMessages, Level.DEBUG);
258 }
259
260 LogMessageWithLevel exhFailureMessages[] = new LogMessageWithLevel[] {
261 new LogMessageWithLevel("Recalculate Used Memory \\(ms\\):", Level.DEBUG),
262 new LogMessageWithLevel("Restore Preserved Marks \\(ms\\):", Level.DEBUG),
263 new LogMessageWithLevel("Restore Evacuation Failed Regions \\(ms\\):", Level.DEBUG),
264 new LogMessageWithLevel("Process Evacuation Failed Regions \\(ms\\):", Level.DEBUG),
265 new LogMessageWithLevel("Evacuation Failed Regions:", Level.DEBUG),
266 new LogMessageWithLevel("Pinned Regions:", Level.DEBUG),
267 new LogMessageWithLevel("Allocation Failed Regions:", Level.DEBUG),
268 };
269
270 private void testWithEvacuationFailureLogs() throws Exception {
271 OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
272 "-Xmx32M",
273 "-Xmn16M",
274 "-XX:+G1GCAllocationFailureALot",
275 "-XX:G1GCAllocationFailureALotCount=100",
276 "-XX:G1GCAllocationFailureALotInterval=1",
277 "-XX:+UnlockDiagnosticVMOptions",
278 "-Xlog:gc+phases=debug",
279 GCTestWithAllocationFailure.class.getName());
280
281 checkMessagesAtLevel(output, exhFailureMessages, Level.DEBUG);
282 output.shouldHaveExitValue(0);
283
284 output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
285 "-Xmx32M",
286 "-Xmn16M",
287 "-Xms32M",
288 "-XX:+UnlockDiagnosticVMOptions",
289 "-Xlog:gc+phases=trace",
290 GCTestWithAllocationFailure.class.getName());
291
292 checkMessagesAtLevel(output, exhFailureMessages, Level.TRACE);
293 output.shouldHaveExitValue(0);
294 }
295
296 LogMessageWithLevel concurrentStartMessages[] = new LogMessageWithLevel[] {
297 new LogMessageWithLevel("Reset Marking State", Level.DEBUG),
298 new LogMessageWithLevel("Note Start Of Mark", Level.DEBUG),
299 };
300
301 private void testWithConcurrentStart() throws Exception {
302 OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
303 "-Xmx10M",
304 "-Xbootclasspath/a:.",
305 "-Xlog:gc*=debug",
306 "-XX:+UnlockDiagnosticVMOptions",
307 "-XX:+WhiteBoxAPI",
308 GCTestWithConcurrentStart.class.getName());
309
310 checkMessagesAtLevel(output, concurrentStartMessages, Level.TRACE);
311 output.shouldHaveExitValue(0);
312 }
313
314 private void testExpandHeap() throws Exception {
315 OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
316 "-Xmx10M",
317 "-Xbootclasspath/a:.",
318 "-Xlog:gc+ergo+heap=debug",
319 "-XX:+UnlockDiagnosticVMOptions",
320 "-XX:+WhiteBoxAPI",
321 GCTest.class.getName());
322
323 output.shouldContain("Expand the heap. requested expansion amount: ");
324 output.shouldContain("B expansion amount: ");
325 output.shouldHaveExitValue(0);
326 }
327
328
329 static class GCTest {
330 private static byte[] garbage;
331 public static void main(String [] args) {
332 System.out.println("Creating garbage");
333 // create 128MB of garbage. This should result in at least one GC
334 for (int i = 0; i < 1024; i++) {
335 garbage = new byte[128 * 1024];
336 }
337 System.out.println("Done");
338 }
339 }
340
341 static class GCTestWithAllocationFailure {
342 private static byte[] garbage;
343 private static byte[] largeObject;
344 private static Object[] holder = new Object[200]; // Must be larger than G1GCAllocationFailureALotCount
345
346 public static void main(String [] args) {
347 largeObject = new byte[16*1024*1024];
348 System.out.println("Creating garbage");
349 // Create 16 MB of garbage. This should result in at least one GC,
350 // (Heap size is 32M, we use 17MB for the large object above)
351 // which is larger than G1GCAllocationFailureALotInterval.
352 for (int i = 0; i < 16 * 1024; i++) {
353 holder[i % holder.length] = new byte[1024];
354 }
355 System.out.println("Done");
356 }
357 }
358
359 static class GCTestWithConcurrentStart {
360 public static void main(String [] args) {
361 jdk.test.whitebox.WhiteBox WB = jdk.test.whitebox.WhiteBox.getWhiteBox();
362 WB.g1StartConcurrentGC();
363 }
364 }
365
366 }