8269022: Put evacuation failure string directly into gc=info log message

Reviewed-by: iwalulya, lkorinth, kbarrett

Author: Thomas Schatzl

src/hotspot/share/gc/g1/g1CollectedHeap.cpp

@@ -2877,17 +2877,6 @@ void G1CollectedHeap::expand_heap_after_young_collection(){
   }
 }
 
-void G1CollectedHeap::set_young_gc_name(char* young_gc_name) {
-  G1GCPauseType pause_type =
-    // The strings for all Concurrent Start pauses are the same, so the parameter
-    // does not matter here.
-    collector_state()->young_gc_pause_type(false /* concurrent_operation_is_full_mark */);
-  snprintf(young_gc_name,
-           MaxYoungGCNameLength,
-           "Pause Young (%s)",
-           G1GCPauseTypeHelper::to_string(pause_type));
-}
-
 bool G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
   assert_at_safepoint_on_vm_thread();
   guarantee(!is_gc_active(), "collection is not reentrant");
@@ -2915,6 +2904,46 @@ void G1CollectedHeap::gc_tracer_report_gc_end(bool concurrent_operation_is_full_
   _gc_timer_stw->time_partitions());
 }
 
+// GCTraceTime wrapper that constructs the message according to GC pause type and
+// GC cause.
+// The code relies on the fact that GCTraceTimeWrapper stores the string passed
+// initially as a reference only, so that we can modify it as needed.
+class G1YoungGCTraceTime {
+  G1GCPauseType _pause_type;
+  GCCause::Cause _pause_cause;
+
+  static const uint MaxYoungGCNameLength = 128;
+  char _young_gc_name_data[MaxYoungGCNameLength];
+
+  GCTraceTime(Info, gc) _tt;
+
+  const char* update_young_gc_name() {
+    snprintf(_young_gc_name_data,
+             MaxYoungGCNameLength,
+             "Pause Young (%s) (%s)%s",
+             G1GCPauseTypeHelper::to_string(_pause_type),
+             GCCause::to_string(_pause_cause),
+             G1CollectedHeap::heap()->evacuation_failed() ? " (Evacuation Failure)" : "");
+    return _young_gc_name_data;
+  }
+
+public:
+  G1YoungGCTraceTime(GCCause::Cause cause) :
+    // Take snapshot of current pause type at start as it may be modified during gc.
+    // The strings for all Concurrent Start pauses are the same, so the parameter
+    // does not matter here.
+    _pause_type(G1CollectedHeap::heap()->collector_state()->young_gc_pause_type(false /* concurrent_operation_is_full_mark */)),
+    _pause_cause(cause),
+    // Fake a "no cause" and manually add the correct string in update_young_gc_name()
+    // to make the string look more natural.
+    _tt(update_young_gc_name(), NULL, GCCause::_no_gc, true) {
+  }
+
+  ~G1YoungGCTraceTime() {
+    update_young_gc_name();
+  }
+};
+
 void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_pause_time_ms) {
   GCIdMark gc_id_mark;
 
@@ -2960,10 +2989,7 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
 
     GCTraceCPUTime tcpu;
 
-    char young_gc_name[MaxYoungGCNameLength];
-    set_young_gc_name(young_gc_name);
-
-    GCTraceTime(Info, gc) tm(young_gc_name, NULL, gc_cause(), true);
+    G1YoungGCTraceTime tm(gc_cause());
 
     uint active_workers = WorkerPolicy::calc_active_workers(workers()->total_workers(),
                                                             workers()->active_workers(),
@@ -3052,11 +3078,6 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
       gc_epilogue(false);
     }
 
-    // Print the remainder of the GC log output.
-    if (evacuation_failed()) {
-      log_info(gc)("To-space exhausted");
-    }
-
     policy()->print_phases();
     heap_transition.print();
 

src/hotspot/share/gc/g1/g1CollectedHeap.hpp

@@ -396,11 +396,6 @@ class G1CollectedHeap : public CollectedHeap {
 #define assert_used_and_recalculate_used_equal(g1h) do {} while(0)
 #endif
 
-  static const uint MaxYoungGCNameLength = 128;
-  // Sets given young_gc_name to the canonical young gc pause string. Young_gc_name
-  // must be at least of length MaxYoungGCNameLength.
-  void set_young_gc_name(char* young_gc_name);
-
   // The young region list.
   G1EdenRegions _eden;
   G1SurvivorRegions _survivor;

test/hotspot/jtreg/gc/g1/TestEvacuationFailure.java

@@ -0,0 +1,82 @@
+/*
+ * Copyright (c) 2021, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+package gc.g1;
+
+/*
+ * @test TestEvacuationFailure
+ * @summary Ensure the output for a minor GC with G1 that has evacuation failure contains the correct strings.
+ * @requires vm.gc.G1
+ * @requires vm.debug
+ * @library /test/lib
+ * @modules java.base/jdk.internal.misc
+ *          java.management
+ * @build sun.hotspot.WhiteBox
+ * @run driver jdk.test.lib.helpers.ClassFileInstaller sun.hotspot.WhiteBox
+ * @run main/othervm -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI
+ *                   gc.g1.TestEvacuationFailure
+ */
+
+import jdk.test.lib.process.OutputAnalyzer;
+import jdk.test.lib.Platform;
+import jdk.test.lib.process.ProcessTools;
+
+public class TestEvacuationFailure {
+
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                                  "-Xmx32M",
+                                                                  "-Xmn16M",
+                                                                  "-XX:+G1EvacuationFailureALot",
+                                                                  "-XX:G1EvacuationFailureALotCount=100",
+                                                                  "-XX:G1EvacuationFailureALotInterval=1",
+                                                                  "-XX:+UnlockDiagnosticVMOptions",
+                                                                  "-XX:-G1UsePreventiveGC",
+                                                                  "-Xlog:gc",
+                                                                  GCTestWithEvacuationFailure.class.getName());
+
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        System.out.println(output.getStdout());
+        output.shouldContain("(Evacuation Failure)");
+        output.shouldHaveExitValue(0);
+    }
+
+    static class GCTestWithEvacuationFailure {
+        private static byte[] garbage;
+        private static byte[] largeObject;
+        private static Object[] holder = new Object[200]; // Must be larger than G1EvacuationFailureALotCount
+
+        public static void main(String [] args) {
+            largeObject = new byte[16 * 1024 * 1024];
+            System.out.println("Creating garbage");
+            // Create 16 MB of garbage. This should result in at least one GC,
+            // (Heap size is 32M, we use 17MB for the large object above)
+            // which is larger than G1EvacuationFailureALotInterval.
+            for (int i = 0; i < 16 * 1024; i++) {
+                holder[i % holder.length] = new byte[1024];
+            }
+            System.out.println("Done");
+        }
+    }
+}
+

test/hotspot/jtreg/gc/g1/plab/TestPLABEvacuationFailure.java

@@ -196,7 +196,7 @@ private static Map<Long, PlabInfo> getEvacFailureOldStats() {
 
     private static List<Long> getGcIdPlabEvacFailures(OutputAnalyzer out) {
         return out.asLines().stream()
-                .filter(line -> line.contains("space exhausted"))
+                .filter(line -> line.contains("(Evacuation Failure)"))
                 .map(line -> LogParser.getGcIdFromLine(line, GC_ID_PATTERN))
                 .collect(Collectors.toList());
     }