6855834: G1: minimize the output when -XX:+PrintHeapAtGC is set

Summary: Changing the behavior of -XX:+PrintHeapAtGC for G1 from printing lengthy, per-region information to instead printing a concise summary.
Reviewed-by: ysr, apetrusenko, jcoomes

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

@@ -902,6 +902,10 @@ void G1CollectedHeap::do_collection(bool full, bool clear_all_soft_refs,
                                     size_t word_size) {
   ResourceMark rm;
 
+  if (PrintHeapAtGC) {
+    Universe::print_heap_before_gc();
+  }
+
   if (full && DisableExplicitGC) {
     gclog_or_tty->print("\n\n\nDisabling Explicit GC\n\n\n");
     return;
@@ -927,7 +931,7 @@ void G1CollectedHeap::do_collection(bool full, bool clear_all_soft_refs,
     g1_policy()->record_full_collection_start();
 
     gc_prologue(true);
-    increment_total_collections();
+    increment_total_collections(true /* full gc */);
 
     size_t g1h_prev_used = used();
     assert(used() == recalculate_used(), "Should be equal");
@@ -1066,6 +1070,10 @@ void G1CollectedHeap::do_collection(bool full, bool clear_all_soft_refs,
     assert( check_young_list_empty(false, false),
             "young list should be empty at this point");
   }
+
+  if (PrintHeapAtGC) {
+    Universe::print_heap_after_gc();
+  }
 }
 
 void G1CollectedHeap::do_full_collection(bool clear_all_soft_refs) {
@@ -2325,9 +2333,37 @@ public:
   }
 };
 
-void G1CollectedHeap::print() const { print_on(gclog_or_tty); }
+void G1CollectedHeap::print() const { print_on(tty); }
 
 void G1CollectedHeap::print_on(outputStream* st) const {
+  print_on(st, PrintHeapAtGCExtended);
+}
+
+void G1CollectedHeap::print_on(outputStream* st, bool extended) const {
+  st->print(" %-20s", "garbage-first heap");
+  st->print(" total " SIZE_FORMAT "K, used " SIZE_FORMAT "K",
+            capacity()/K, used()/K);
+  st->print(" [" INTPTR_FORMAT ", " INTPTR_FORMAT ", " INTPTR_FORMAT ")",
+            _g1_storage.low_boundary(),
+            _g1_storage.high(),
+            _g1_storage.high_boundary());
+  st->cr();
+  st->print("  region size " SIZE_FORMAT "K, ",
+            HeapRegion::GrainBytes/K);
+  size_t young_regions = _young_list->length();
+  st->print(SIZE_FORMAT " young (" SIZE_FORMAT "K), ",
+            young_regions, young_regions * HeapRegion::GrainBytes / K);
+  size_t survivor_regions = g1_policy()->recorded_survivor_regions();
+  st->print(SIZE_FORMAT " survivors (" SIZE_FORMAT "K)",
+            survivor_regions, survivor_regions * HeapRegion::GrainBytes / K);
+  st->cr();
+  perm()->as_gen()->print_on(st);
+  if (extended) {
+    print_on_extended(st);
+  }
+}
+
+void G1CollectedHeap::print_on_extended(outputStream* st) const {
   PrintRegionClosure blk(st);
   _hrs->iterate(&blk);
 }
@@ -2408,10 +2444,6 @@ G1CollectedHeap* G1CollectedHeap::heap() {
 }
 
 void G1CollectedHeap::gc_prologue(bool full /* Ignored */) {
-  if (PrintHeapAtGC){
-    gclog_or_tty->print_cr(" {Heap before GC collections=%d:", total_collections());
-    Universe::print();
-  }
   assert(InlineCacheBuffer::is_empty(), "should have cleaned up ICBuffer");
   // Call allocation profiler
   AllocationProfiler::iterate_since_last_gc();
@@ -2425,12 +2457,6 @@ void G1CollectedHeap::gc_epilogue(bool full /* Ignored */) {
   // is set.
   COMPILER2_PRESENT(assert(DerivedPointerTable::is_empty(),
                         "derived pointer present"));
-
-  if (PrintHeapAtGC){
-    gclog_or_tty->print_cr(" Heap after GC collections=%d:", total_collections());
-    Universe::print();
-    gclog_or_tty->print("} ");
-  }
 }
 
 void G1CollectedHeap::do_collection_pause() {
@@ -2559,241 +2585,250 @@ G1CollectedHeap::cleanup_surviving_young_words() {
 
 void
 G1CollectedHeap::do_collection_pause_at_safepoint() {
-  char verbose_str[128];
-  sprintf(verbose_str, "GC pause ");
-  if (g1_policy()->in_young_gc_mode()) {
-    if (g1_policy()->full_young_gcs())
-      strcat(verbose_str, "(young)");
-    else
-      strcat(verbose_str, "(partial)");
+  if (PrintHeapAtGC) {
+    Universe::print_heap_before_gc();
   }
-  if (g1_policy()->should_initiate_conc_mark())
-    strcat(verbose_str, " (initial-mark)");
 
-  GCCauseSetter x(this, GCCause::_g1_inc_collection_pause);
+  {
+    char verbose_str[128];
+    sprintf(verbose_str, "GC pause ");
+    if (g1_policy()->in_young_gc_mode()) {
+      if (g1_policy()->full_young_gcs())
+        strcat(verbose_str, "(young)");
+      else
+        strcat(verbose_str, "(partial)");
+    }
+    if (g1_policy()->should_initiate_conc_mark())
+      strcat(verbose_str, " (initial-mark)");
 
-  // if PrintGCDetails is on, we'll print long statistics information
-  // in the collector policy code, so let's not print this as the output
-  // is messy if we do.
-  gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
-  TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
-  TraceTime t(verbose_str, PrintGC && !PrintGCDetails, true, gclog_or_tty);
+    GCCauseSetter x(this, GCCause::_g1_inc_collection_pause);
 
-  ResourceMark rm;
-  assert(SafepointSynchronize::is_at_safepoint(), "should be at safepoint");
-  assert(Thread::current() == VMThread::vm_thread(), "should be in vm thread");
-  guarantee(!is_gc_active(), "collection is not reentrant");
-  assert(regions_accounted_for(), "Region leakage!");
+    // if PrintGCDetails is on, we'll print long statistics information
+    // in the collector policy code, so let's not print this as the output
+    // is messy if we do.
+    gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
+    TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
+    TraceTime t(verbose_str, PrintGC && !PrintGCDetails, true, gclog_or_tty);
 
-  increment_gc_time_stamp();
+    ResourceMark rm;
+    assert(SafepointSynchronize::is_at_safepoint(), "should be at safepoint");
+    assert(Thread::current() == VMThread::vm_thread(), "should be in vm thread");
+    guarantee(!is_gc_active(), "collection is not reentrant");
+    assert(regions_accounted_for(), "Region leakage!");
 
-  if (g1_policy()->in_young_gc_mode()) {
-    assert(check_young_list_well_formed(),
-                "young list should be well formed");
-  }
+    increment_gc_time_stamp();
 
-  if (GC_locker::is_active()) {
-    return; // GC is disabled (e.g. JNI GetXXXCritical operation)
-  }
+    if (g1_policy()->in_young_gc_mode()) {
+      assert(check_young_list_well_formed(),
+             "young list should be well formed");
+    }
 
-  bool abandoned = false;
-  { // Call to jvmpi::post_class_unload_events must occur outside of active GC
-    IsGCActiveMark x;
+    if (GC_locker::is_active()) {
+      return; // GC is disabled (e.g. JNI GetXXXCritical operation)
+    }
 
-    gc_prologue(false);
-    increment_total_collections();
+    bool abandoned = false;
+    { // Call to jvmpi::post_class_unload_events must occur outside of active GC
+      IsGCActiveMark x;
+
+      gc_prologue(false);
+      increment_total_collections(false /* full gc */);
 
 #if G1_REM_SET_LOGGING
-    gclog_or_tty->print_cr("\nJust chose CS, heap:");
-    print();
+      gclog_or_tty->print_cr("\nJust chose CS, heap:");
+      print();
 #endif
 
-    if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) {
-      HandleMark hm;  // Discard invalid handles created during verification
-      prepare_for_verify();
-      gclog_or_tty->print(" VerifyBeforeGC:");
-      Universe::verify(false);
-    }
+      if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) {
+        HandleMark hm;  // Discard invalid handles created during verification
+        prepare_for_verify();
+        gclog_or_tty->print(" VerifyBeforeGC:");
+        Universe::verify(false);
+      }
 
-    COMPILER2_PRESENT(DerivedPointerTable::clear());
+      COMPILER2_PRESENT(DerivedPointerTable::clear());
 
-    // We want to turn off ref discovery, if necessary, and turn it back on
-    // on again later if we do.
-    bool was_enabled = ref_processor()->discovery_enabled();
-    if (was_enabled) ref_processor()->disable_discovery();
+      // We want to turn off ref discovery, if necessary, and turn it back on
+      // on again later if we do.
+      bool was_enabled = ref_processor()->discovery_enabled();
+      if (was_enabled) ref_processor()->disable_discovery();
 
-    // Forget the current alloc region (we might even choose it to be part
-    // of the collection set!).
-    abandon_cur_alloc_region();
+      // Forget the current alloc region (we might even choose it to be part
+      // of the collection set!).
+      abandon_cur_alloc_region();
 
-    // The elapsed time induced by the start time below deliberately elides
-    // the possible verification above.
-    double start_time_sec = os::elapsedTime();
-    GCOverheadReporter::recordSTWStart(start_time_sec);
-    size_t start_used_bytes = used();
-    if (!G1ConcMark) {
-      do_sync_mark();
-    }
+      // The elapsed time induced by the start time below deliberately elides
+      // the possible verification above.
+      double start_time_sec = os::elapsedTime();
+      GCOverheadReporter::recordSTWStart(start_time_sec);
+      size_t start_used_bytes = used();
+      if (!G1ConcMark) {
+        do_sync_mark();
+      }
 
-    g1_policy()->record_collection_pause_start(start_time_sec,
-                                               start_used_bytes);
+      g1_policy()->record_collection_pause_start(start_time_sec,
+                                                 start_used_bytes);
 
-    guarantee(_in_cset_fast_test == NULL, "invariant");
-    guarantee(_in_cset_fast_test_base == NULL, "invariant");
-    _in_cset_fast_test_length = max_regions();
-    _in_cset_fast_test_base =
+      guarantee(_in_cset_fast_test == NULL, "invariant");
+      guarantee(_in_cset_fast_test_base == NULL, "invariant");
+      _in_cset_fast_test_length = max_regions();
+      _in_cset_fast_test_base =
                              NEW_C_HEAP_ARRAY(bool, _in_cset_fast_test_length);
-    memset(_in_cset_fast_test_base, false,
+      memset(_in_cset_fast_test_base, false,
                                      _in_cset_fast_test_length * sizeof(bool));
-    // We're biasing _in_cset_fast_test to avoid subtracting the
-    // beginning of the heap every time we want to index; basically
-    // it's the same with what we do with the card table.
-    _in_cset_fast_test = _in_cset_fast_test_base -
+      // We're biasing _in_cset_fast_test to avoid subtracting the
+      // beginning of the heap every time we want to index; basically
+      // it's the same with what we do with the card table.
+      _in_cset_fast_test = _in_cset_fast_test_base -
               ((size_t) _g1_reserved.start() >> HeapRegion::LogOfHRGrainBytes);
 
 #if SCAN_ONLY_VERBOSE
-    _young_list->print();
+      _young_list->print();
 #endif // SCAN_ONLY_VERBOSE
 
-    if (g1_policy()->should_initiate_conc_mark()) {
-      concurrent_mark()->checkpointRootsInitialPre();
-    }
-    save_marks();
-
-    // We must do this before any possible evacuation that should propagate
-    // marks.
-    if (mark_in_progress()) {
-      double start_time_sec = os::elapsedTime();
+      if (g1_policy()->should_initiate_conc_mark()) {
+        concurrent_mark()->checkpointRootsInitialPre();
+      }
+      save_marks();
 
-      _cm->drainAllSATBBuffers();
-      double finish_mark_ms = (os::elapsedTime() - start_time_sec) * 1000.0;
-      g1_policy()->record_satb_drain_time(finish_mark_ms);
+      // We must do this before any possible evacuation that should propagate
+      // marks.
+      if (mark_in_progress()) {
+        double start_time_sec = os::elapsedTime();
 
-    }
-    // Record the number of elements currently on the mark stack, so we
-    // only iterate over these.  (Since evacuation may add to the mark
-    // stack, doing more exposes race conditions.)  If no mark is in
-    // progress, this will be zero.
-    _cm->set_oops_do_bound();
+        _cm->drainAllSATBBuffers();
+        double finish_mark_ms = (os::elapsedTime() - start_time_sec) * 1000.0;
+        g1_policy()->record_satb_drain_time(finish_mark_ms);
+      }
+      // Record the number of elements currently on the mark stack, so we
+      // only iterate over these.  (Since evacuation may add to the mark
+      // stack, doing more exposes race conditions.)  If no mark is in
+      // progress, this will be zero.
+      _cm->set_oops_do_bound();
 
-    assert(regions_accounted_for(), "Region leakage.");
+      assert(regions_accounted_for(), "Region leakage.");
 
-    if (mark_in_progress())
-      concurrent_mark()->newCSet();
+      if (mark_in_progress())
+        concurrent_mark()->newCSet();
 
-    // Now choose the CS.
-    g1_policy()->choose_collection_set();
+      // Now choose the CS.
+      g1_policy()->choose_collection_set();
 
-    // We may abandon a pause if we find no region that will fit in the MMU
-    // pause.
-    bool abandoned = (g1_policy()->collection_set() == NULL);
+      // We may abandon a pause if we find no region that will fit in the MMU
+      // pause.
+      bool abandoned = (g1_policy()->collection_set() == NULL);
 
-    // Nothing to do if we were unable to choose a collection set.
-    if (!abandoned) {
+      // Nothing to do if we were unable to choose a collection set.
+      if (!abandoned) {
 #if G1_REM_SET_LOGGING
-      gclog_or_tty->print_cr("\nAfter pause, heap:");
-      print();
+        gclog_or_tty->print_cr("\nAfter pause, heap:");
+        print();
 #endif
 
-      setup_surviving_young_words();
+        setup_surviving_young_words();
 
-      // Set up the gc allocation regions.
-      get_gc_alloc_regions();
+        // Set up the gc allocation regions.
+        get_gc_alloc_regions();
 
-      // Actually do the work...
-      evacuate_collection_set();
-      free_collection_set(g1_policy()->collection_set());
-      g1_policy()->clear_collection_set();
+        // Actually do the work...
+        evacuate_collection_set();
+        free_collection_set(g1_policy()->collection_set());
+        g1_policy()->clear_collection_set();
 
-      FREE_C_HEAP_ARRAY(bool, _in_cset_fast_test_base);
-      // this is more for peace of mind; we're nulling them here and
-      // we're expecting them to be null at the beginning of the next GC
-      _in_cset_fast_test = NULL;
-      _in_cset_fast_test_base = NULL;
+        FREE_C_HEAP_ARRAY(bool, _in_cset_fast_test_base);
+        // this is more for peace of mind; we're nulling them here and
+        // we're expecting them to be null at the beginning of the next GC
+        _in_cset_fast_test = NULL;
+        _in_cset_fast_test_base = NULL;
 
-      release_gc_alloc_regions(false /* totally */);
+        release_gc_alloc_regions(false /* totally */);
 
-      cleanup_surviving_young_words();
+        cleanup_surviving_young_words();
 
-      if (g1_policy()->in_young_gc_mode()) {
-        _young_list->reset_sampled_info();
-        assert(check_young_list_empty(true),
-               "young list should be empty");
+        if (g1_policy()->in_young_gc_mode()) {
+          _young_list->reset_sampled_info();
+          assert(check_young_list_empty(true),
+                 "young list should be empty");
 
 #if SCAN_ONLY_VERBOSE
-        _young_list->print();
+          _young_list->print();
 #endif // SCAN_ONLY_VERBOSE
 
-        g1_policy()->record_survivor_regions(_young_list->survivor_length(),
-                                             _young_list->first_survivor_region(),
-                                             _young_list->last_survivor_region());
-        _young_list->reset_auxilary_lists();
+          g1_policy()->record_survivor_regions(_young_list->survivor_length(),
+                                          _young_list->first_survivor_region(),
+                                          _young_list->last_survivor_region());
+          _young_list->reset_auxilary_lists();
+        }
+      } else {
+        COMPILER2_PRESENT(DerivedPointerTable::update_pointers());
       }
-    } else {
-      COMPILER2_PRESENT(DerivedPointerTable::update_pointers());
-    }
 
-    if (evacuation_failed()) {
-      _summary_bytes_used = recalculate_used();
-    } else {
-      // The "used" of the the collection set have already been subtracted
-      // when they were freed.  Add in the bytes evacuated.
-      _summary_bytes_used += g1_policy()->bytes_in_to_space();
-    }
+      if (evacuation_failed()) {
+        _summary_bytes_used = recalculate_used();
+      } else {
+        // The "used" of the the collection set have already been subtracted
+        // when they were freed.  Add in the bytes evacuated.
+        _summary_bytes_used += g1_policy()->bytes_in_to_space();
+      }
 
-    if (g1_policy()->in_young_gc_mode() &&
-        g1_policy()->should_initiate_conc_mark()) {
-      concurrent_mark()->checkpointRootsInitialPost();
-      set_marking_started();
-      doConcurrentMark();
-    }
+      if (g1_policy()->in_young_gc_mode() &&
+          g1_policy()->should_initiate_conc_mark()) {
+        concurrent_mark()->checkpointRootsInitialPost();
+        set_marking_started();
+        doConcurrentMark();
+      }
 
 #if SCAN_ONLY_VERBOSE
-    _young_list->print();
+      _young_list->print();
 #endif // SCAN_ONLY_VERBOSE
 
-    double end_time_sec = os::elapsedTime();
-    double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS;
-    g1_policy()->record_pause_time_ms(pause_time_ms);
-    GCOverheadReporter::recordSTWEnd(end_time_sec);
-    g1_policy()->record_collection_pause_end(abandoned);
+      double end_time_sec = os::elapsedTime();
+      double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS;
+      g1_policy()->record_pause_time_ms(pause_time_ms);
+      GCOverheadReporter::recordSTWEnd(end_time_sec);
+      g1_policy()->record_collection_pause_end(abandoned);
 
-    assert(regions_accounted_for(), "Region leakage.");
+      assert(regions_accounted_for(), "Region leakage.");
 
-    if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) {
-      HandleMark hm;  // Discard invalid handles created during verification
-      gclog_or_tty->print(" VerifyAfterGC:");
-      prepare_for_verify();
-      Universe::verify(false);
-    }
+      if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) {
+        HandleMark hm;  // Discard invalid handles created during verification
+        gclog_or_tty->print(" VerifyAfterGC:");
+        prepare_for_verify();
+        Universe::verify(false);
+      }
 
-    if (was_enabled) ref_processor()->enable_discovery();
+      if (was_enabled) ref_processor()->enable_discovery();
 
-    {
-      size_t expand_bytes = g1_policy()->expansion_amount();
-      if (expand_bytes > 0) {
-        size_t bytes_before = capacity();
-        expand(expand_bytes);
+      {
+        size_t expand_bytes = g1_policy()->expansion_amount();
+        if (expand_bytes > 0) {
+          size_t bytes_before = capacity();
+          expand(expand_bytes);
+        }
       }
-    }
 
-    if (mark_in_progress()) {
-      concurrent_mark()->update_g1_committed();
-    }
+      if (mark_in_progress()) {
+        concurrent_mark()->update_g1_committed();
+      }
 
 #ifdef TRACESPINNING
-    ParallelTaskTerminator::print_termination_counts();
+      ParallelTaskTerminator::print_termination_counts();
 #endif
 
-    gc_epilogue(false);
-  }
+      gc_epilogue(false);
+    }
+
+    assert(verify_region_lists(), "Bad region lists.");
 
-  assert(verify_region_lists(), "Bad region lists.");
+    if (ExitAfterGCNum > 0 && total_collections() == ExitAfterGCNum) {
+      gclog_or_tty->print_cr("Stopping after GC #%d", ExitAfterGCNum);
+      print_tracing_info();
+      vm_exit(-1);
+    }
+  }
 
-  if (ExitAfterGCNum > 0 && total_collections() == ExitAfterGCNum) {
-    gclog_or_tty->print_cr("Stopping after GC #%d", ExitAfterGCNum);
-    print_tracing_info();
-    vm_exit(-1);
+  if (PrintHeapAtGC) {
+    Universe::print_heap_after_gc();
   }
 }
 
@@ -5357,7 +5392,7 @@ void G1CollectedHeap::tear_down_region_lists() {
   assert(_free_region_list == NULL, "Postcondition of loop.");
   if (_free_region_list_size != 0) {
     gclog_or_tty->print_cr("Size is %d.", _free_region_list_size);
-    print();
+    print_on(gclog_or_tty, true /* extended */);
   }
   assert(_free_region_list_size == 0, "Postconditions of loop.");
 }

hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp

@@ -1061,8 +1061,14 @@ public:
 
   // Override; it uses the "prev" marking information
   virtual void verify(bool allow_dirty, bool silent);
+  // Default behavior by calling print(tty);
   virtual void print() const;
+  // This calls print_on(st, PrintHeapAtGCExtended).
   virtual void print_on(outputStream* st) const;
+  // If extended is true, it will print out information for all
+  // regions in the heap by calling print_on_extended(st).
+  virtual void print_on(outputStream* st, bool extended) const;
+  virtual void print_on_extended(outputStream* st) const;
 
   virtual void print_gc_threads_on(outputStream* st) const;
   virtual void gc_threads_do(ThreadClosure* tc) const;

hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp

@@ -1097,6 +1097,10 @@ public:
     _recorded_survivor_tail    = tail;
   }
 
+  size_t recorded_survivor_regions() {
+    return _recorded_survivor_regions;
+  }
+
   void record_thread_age_table(ageTable* age_table)
   {
     _survivors_age_table.merge_par(age_table);

hotspot/src/share/vm/gc_implementation/g1/heapRegion.cpp

@@ -703,7 +703,7 @@ void HeapRegion::verify(bool allow_dirty, bool use_prev_marking) const {
   }
   if (vl_cl.failures()) {
     gclog_or_tty->print_cr("Heap:");
-    G1CollectedHeap::heap()->print();
+    G1CollectedHeap::heap()->print_on(gclog_or_tty, true /* extended */);
     gclog_or_tty->print_cr("");
   }
   if (VerifyDuringGC &&

hotspot/src/share/vm/runtime/globals.hpp

@@ -1994,6 +1994,10 @@ class CommandLineFlags {
   product_rw(bool, PrintHeapAtGC, false,                                    \
           "Print heap layout before and after each GC")                     \
                                                                             \
+  product_rw(bool, PrintHeapAtGCExtended, false,                            \
+          "Prints extended information about the layout of the heap "       \
+          "when -XX:+PrintHeapAtGC is set")                                 \
+                                                                            \
   product(bool, PrintHeapAtSIGBREAK, true,                                  \
           "Print heap layout in response to SIGBREAK")                      \
                                                                             \