8035654: Add times for evacuation failure handling in "Other" time

Summary: Detailed breakdown of time spent in the evacuation failure handling phases to make the "Other" time roughly correspond to the sum of its parts.
Reviewed-by: jwilhelm, jmasa

src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp

@@ -2360,8 +2360,12 @@ public:
 };
 
 size_t G1CollectedHeap::recalculate_used() const {
+  double recalculate_used_start = os::elapsedTime();
+
   SumUsedClosure blk;
   heap_region_iterate(&blk);
+
+  g1_policy()->phase_times()->record_evac_fail_recalc_used_time((os::elapsedTime() - recalculate_used_start) * 1000.0);
   return blk.result();
 }
 
@@ -4394,6 +4398,8 @@ void G1CollectedHeap::finalize_for_evac_failure() {
 void G1CollectedHeap::remove_self_forwarding_pointers() {
   assert(check_cset_heap_region_claim_values(HeapRegion::InitialClaimValue), "sanity");
 
+  double remove_self_forwards_start = os::elapsedTime();
+
   G1ParRemoveSelfForwardPtrsTask rsfp_task(this);
 
   if (G1CollectedHeap::use_parallel_gc_threads()) {
@@ -4421,6 +4427,8 @@ void G1CollectedHeap::remove_self_forwarding_pointers() {
   }
   _objs_with_preserved_marks.clear(true);
   _preserved_marks_of_objs.clear(true);
+
+  g1_policy()->phase_times()->record_evac_fail_remove_self_forwards((os::elapsedTime() - remove_self_forwards_start) * 1000.0);
 }
 
 void G1CollectedHeap::push_on_evac_failure_scan_stack(oop obj) {

src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp

@@ -309,6 +309,16 @@ void G1GCPhaseTimes::print(double pause_time_sec) {
   if (_cur_verify_before_time_ms > 0.0) {
     print_stats(2, "Verify Before", _cur_verify_before_time_ms);
   }
+  if (G1CollectedHeap::heap()->evacuation_failed()) {
+    double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
+      _cur_evac_fail_restore_remsets;
+    print_stats(2, "Evacuation Failure", evac_fail_handling);
+    if (G1Log::finest()) {
+      print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
+      print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
+      print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
+    }
+  }
   print_stats(2, "Choose CSet",
     (_recorded_young_cset_choice_time_ms +
     _recorded_non_young_cset_choice_time_ms));

src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp

@@ -133,6 +133,10 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
   double _cur_strong_code_root_migration_time_ms;
   double _cur_strong_code_root_purge_time_ms;
 
+  double _cur_evac_fail_recalc_used;
+  double _cur_evac_fail_restore_remsets;
+  double _cur_evac_fail_remove_self_forwards;
+
   double _cur_clear_ct_time_ms;
   double _cur_ref_proc_time_ms;
   double _cur_ref_enq_time_ms;
@@ -230,6 +234,18 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
     _cur_strong_code_root_purge_time_ms = ms;
   }
 
+  void record_evac_fail_recalc_used_time(double ms) {
+    _cur_evac_fail_recalc_used = ms;
+  }
+
+  void record_evac_fail_restore_remsets(double ms) {
+    _cur_evac_fail_restore_remsets = ms;
+  }
+
+  void record_evac_fail_remove_self_forwards(double ms) {
+    _cur_evac_fail_remove_self_forwards = ms;
+  }
+
   void record_ref_proc_time(double ms) {
     _cur_ref_proc_time_ms = ms;
   }

src/share/vm/gc_implementation/g1/g1RemSet.cpp

@@ -463,8 +463,9 @@ void G1RemSet::cleanup_after_oops_into_collection_set_do() {
   int into_cset_n_buffers = into_cset_dcqs.completed_buffers_num();
 
   if (_g1->evacuation_failed()) {
-    // Restore remembered sets for the regions pointing into the collection set.
+    double restore_remembered_set_start = os::elapsedTime();
 
+    // Restore remembered sets for the regions pointing into the collection set.
     if (G1DeferredRSUpdate) {
       // If deferred RS updates are enabled then we just need to transfer
       // the completed buffers from (a) the DirtyCardQueueSet used to hold
@@ -483,6 +484,8 @@ void G1RemSet::cleanup_after_oops_into_collection_set_do() {
       }
       assert(n_completed_buffers == into_cset_n_buffers, "missed some buffers");
     }
+
+    _g1->g1_policy()->phase_times()->record_evac_fail_restore_remsets((os::elapsedTime() - restore_remembered_set_start) * 1000.0);
   }
 
   // Free any completed buffers in the DirtyCardQueueSet used to hold cards

test/gc/g1/TestGCLogMessages.java

@@ -35,6 +35,11 @@ import com.oracle.java.testlibrary.OutputAnalyzer;
 
 public class TestGCLogMessages {
   public static void main(String[] args) throws Exception {
+    testNormalLogs();
+    testWithToSpaceExhaustionLogs();
+  }
+
+  private static void testNormalLogs() throws Exception {
 
     ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
                                                               "-Xmx10M",
@@ -74,8 +79,43 @@ public class TestGCLogMessages {
     output.shouldContain("[Code Root Purge");
     output.shouldContain("[Young Free CSet");
     output.shouldContain("[Non-Young Free CSet");
+
+    // also check evacuation failure messages once
+    output.shouldNotContain("[Evacuation Failure");
+    output.shouldNotContain("[Recalculate Used");
+    output.shouldNotContain("[Remove Self Forwards");
+    output.shouldNotContain("[Restore RemSet");
     output.shouldHaveExitValue(0);
+  }
+
+  private static void testWithToSpaceExhaustionLogs() throws Exception {
+    ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                               "-Xmx10M",
+                                               "-Xmn5M",
+                                               "-XX:+PrintGCDetails",
+                                               GCTestWithToSpaceExhaustion.class.getName());
 
+    OutputAnalyzer output = new OutputAnalyzer(pb.start());
+    output.shouldContain("[Evacuation Failure");
+    output.shouldNotContain("[Recalculate Used");
+    output.shouldNotContain("[Remove Self Forwards");
+    output.shouldNotContain("[Restore RemSet");
+    output.shouldHaveExitValue(0);
+
+    pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                               "-Xmx10M",
+                                               "-Xmn5M",
+                                               "-XX:+PrintGCDetails",
+                                               "-XX:+UnlockExperimentalVMOptions",
+                                               "-XX:G1LogLevel=finest",
+                                               GCTestWithToSpaceExhaustion.class.getName());
+
+    output = new OutputAnalyzer(pb.start());
+    output.shouldContain("[Evacuation Failure");
+    output.shouldContain("[Recalculate Used");
+    output.shouldContain("[Remove Self Forwards");
+    output.shouldContain("[Restore RemSet");
+    output.shouldHaveExitValue(0);
   }
 
   static class GCTest {
@@ -89,4 +129,19 @@ public class TestGCLogMessages {
       System.out.println("Done");
     }
   }
+
+  static class GCTestWithToSpaceExhaustion {
+    private static byte[] garbage;
+    private static byte[] largeObject;
+    public static void main(String [] args) {
+      largeObject = new byte[5*1024*1024];
+      System.out.println("Creating garbage");
+      // create 128MB of garbage. This should result in at least one GC,
+      // some of them with to-space exhaustion.
+      for (int i = 0; i < 1024; i++) {
+        garbage = new byte[128 * 1024];
+      }
+      System.out.println("Done");
+    }
+  }
 }