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 Evacuation Failed Regions \\(ms\\):", Level.DEBUG),
263         new LogMessageWithLevel("Process Evacuation Failed Regions \\(ms\\):", Level.DEBUG),
264         new LogMessageWithLevel("Evacuation Failed Regions:", Level.DEBUG),
265         new LogMessageWithLevel("Pinned Regions:", Level.DEBUG),
266         new LogMessageWithLevel("Allocation Failed Regions:", Level.DEBUG),
267     };
268 
269     private void testWithEvacuationFailureLogs() throws Exception {
270         OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
271                                                                     "-Xmx32M",
272                                                                     "-Xmn16M",
273                                                                     "-XX:+G1GCAllocationFailureALot",
274                                                                     "-XX:G1GCAllocationFailureALotCount=100",
275                                                                     "-XX:G1GCAllocationFailureALotInterval=1",
276                                                                     "-XX:+UnlockDiagnosticVMOptions",
277                                                                     "-Xlog:gc+phases=debug",
278                                                                     GCTestWithAllocationFailure.class.getName());
279 
280         checkMessagesAtLevel(output, exhFailureMessages, Level.DEBUG);
281         output.shouldHaveExitValue(0);
282 
283         output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
284                                                      "-Xmx32M",
285                                                      "-Xmn16M",
286                                                      "-Xms32M",
287                                                      "-XX:+UnlockDiagnosticVMOptions",
288                                                      "-Xlog:gc+phases=trace",
289                                                      GCTestWithAllocationFailure.class.getName());
290 
291         checkMessagesAtLevel(output, exhFailureMessages, Level.TRACE);
292         output.shouldHaveExitValue(0);
293     }
294 
295     LogMessageWithLevel concurrentStartMessages[] = new LogMessageWithLevel[] {
296         new LogMessageWithLevel("Reset Marking State", Level.DEBUG),
297         new LogMessageWithLevel("Note Start Of Mark", Level.DEBUG),
298     };
299 
300     private void testWithConcurrentStart() throws Exception {
301         OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
302                                                                     "-Xmx10M",
303                                                                     "-Xbootclasspath/a:.",
304                                                                     "-Xlog:gc*=debug",
305                                                                     "-XX:+UnlockDiagnosticVMOptions",
306                                                                     "-XX:+WhiteBoxAPI",
307                                                                     GCTestWithConcurrentStart.class.getName());
308 
309         checkMessagesAtLevel(output, concurrentStartMessages, Level.TRACE);
310         output.shouldHaveExitValue(0);
311     }
312 
313     private void testExpandHeap() throws Exception {
314         OutputAnalyzer output = ProcessTools.executeLimitedTestJava("-XX:+UseG1GC",
315                                                                     "-Xmx10M",
316                                                                     "-Xbootclasspath/a:.",
317                                                                     "-Xlog:gc+ergo+heap=debug",
318                                                                     "-XX:+UnlockDiagnosticVMOptions",
319                                                                     "-XX:+WhiteBoxAPI",
320                                                                     GCTest.class.getName());
321 
322         output.shouldContain("Expand the heap. requested expansion amount: ");
323         output.shouldContain("B expansion amount: ");
324         output.shouldHaveExitValue(0);
325     }
326 
327 
328     static class GCTest {
329         private static byte[] garbage;
330         public static void main(String [] args) {
331             System.out.println("Creating garbage");
332             // create 128MB of garbage. This should result in at least one GC
333             for (int i = 0; i < 1024; i++) {
334                 garbage = new byte[128 * 1024];
335             }
336             System.out.println("Done");
337         }
338     }
339 
340     static class GCTestWithAllocationFailure {
341         private static byte[] garbage;
342         private static byte[] largeObject;
343         private static Object[] holder = new Object[200]; // Must be larger than G1GCAllocationFailureALotCount
344 
345         public static void main(String [] args) {
346             largeObject = new byte[16*1024*1024];
347             System.out.println("Creating garbage");
348             // Create 16 MB of garbage. This should result in at least one GC,
349             // (Heap size is 32M, we use 17MB for the large object above)
350             // which is larger than G1GCAllocationFailureALotInterval.
351             for (int i = 0; i < 16 * 1024; i++) {
352                 holder[i % holder.length] = new byte[1024];
353             }
354             System.out.println("Done");
355         }
356     }
357 
358     static class GCTestWithConcurrentStart {
359         public static void main(String [] args) {
360             jdk.test.whitebox.WhiteBox WB = jdk.test.whitebox.WhiteBox.getWhiteBox();
361             WB.g1StartConcurrentGC();
362         }
363     }
364 
365 }