8010738: G1: Output for full GCs with +PrintGCDetails should contain perm gen size/meta data change info

Include metaspace information (used, allocated, reserved) in the PrintGCDetails output for full GCs.

Reviewed-by: poonam, jmasa, brutisso

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

@@ -1549,7 +1549,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
     }
 
     if (G1Log::finer()) {
-      g1_policy()->print_detailed_heap_transition();
+      g1_policy()->print_detailed_heap_transition(true /* full */);
     }
 
     print_heap_after_gc();

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

@@ -124,9 +124,12 @@ G1CollectorPolicy::G1CollectorPolicy() :
   _last_young_gc(false),
   _last_gc_was_young(false),
 
-  _eden_bytes_before_gc(0),
-  _survivor_bytes_before_gc(0),
-  _capacity_before_gc(0),
+  _eden_used_bytes_before_gc(0),
+  _survivor_used_bytes_before_gc(0),
+  _heap_used_bytes_before_gc(0),
+  _metaspace_used_bytes_before_gc(0),
+  _eden_capacity_bytes_before_gc(0),
+  _heap_capacity_bytes_before_gc(0),
 
   _eden_cset_region_length(0),
   _survivor_cset_region_length(0),
@@ -746,7 +749,7 @@ G1CollectorPolicy::verify_young_ages(HeapRegion* head,
 
 void G1CollectorPolicy::record_full_collection_start() {
   _full_collection_start_sec = os::elapsedTime();
-  record_heap_size_info_at_start();
+  record_heap_size_info_at_start(true /* full */);
   // Release the future to-space so that it is available for compaction into.
   _g1->set_full_collection();
 }
@@ -803,7 +806,7 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec) {
   _trace_gen0_time_data.record_start_collection(s_w_t_ms);
   _stop_world_start = 0.0;
 
-  record_heap_size_info_at_start();
+  record_heap_size_info_at_start(false /* full */);
 
   phase_times()->record_cur_collection_start_sec(start_time_sec);
   _pending_cards = _g1->pending_card_num();
@@ -938,14 +941,6 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
   _mmu_tracker->add_pause(end_time_sec - pause_time_ms/1000.0,
                           end_time_sec, false);
 
-  size_t freed_bytes =
-    _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
-  size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes;
-
-  double survival_fraction =
-    (double)surviving_bytes/
-    (double)_collection_set_bytes_used_before;
-
   if (update_stats) {
     _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
     // this is where we update the allocation rate of the application
@@ -998,6 +993,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
       }
     }
   }
+
   bool new_in_marking_window = _in_marking_window;
   bool new_in_marking_window_im = false;
   if (during_initial_mark_pause()) {
@@ -1083,8 +1079,10 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
     }
     _rs_length_diff_seq->add((double) rs_length_diff);
 
-    size_t copied_bytes = surviving_bytes;
+    size_t freed_bytes = _heap_used_bytes_before_gc - cur_used_bytes;
+    size_t copied_bytes = _collection_set_bytes_used_before - freed_bytes;
     double cost_per_byte_ms = 0.0;
+
     if (copied_bytes > 0) {
       cost_per_byte_ms = phase_times()->average_last_obj_copy_time() / (double) copied_bytes;
       if (_in_marking_window) {
@@ -1148,51 +1146,61 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
   byte_size_in_proper_unit((double)(bytes)),                    \
   proper_unit_for_byte_size((bytes))
 
-void G1CollectorPolicy::record_heap_size_info_at_start() {
+void G1CollectorPolicy::record_heap_size_info_at_start(bool full) {
   YoungList* young_list = _g1->young_list();
-  _eden_bytes_before_gc = young_list->eden_used_bytes();
-  _survivor_bytes_before_gc = young_list->survivor_used_bytes();
-  _capacity_before_gc = _g1->capacity();
-
-  _cur_collection_pause_used_at_start_bytes = _g1->used();
+  _eden_used_bytes_before_gc = young_list->eden_used_bytes();
+  _survivor_used_bytes_before_gc = young_list->survivor_used_bytes();
+  _heap_capacity_bytes_before_gc = _g1->capacity();
+  _heap_used_bytes_before_gc = _g1->used();
   _cur_collection_pause_used_regions_at_start = _g1->used_regions();
 
-  size_t eden_capacity_before_gc =
-         (_young_list_target_length * HeapRegion::GrainBytes) - _survivor_bytes_before_gc;
+  _eden_capacity_bytes_before_gc =
+         (_young_list_target_length * HeapRegion::GrainBytes) - _survivor_used_bytes_before_gc;
 
-  _prev_eden_capacity = eden_capacity_before_gc;
+  if (full) {
+    _metaspace_used_bytes_before_gc = MetaspaceAux::allocated_used_bytes();
+  }
 }
 
 void G1CollectorPolicy::print_heap_transition() {
   _g1->print_size_transition(gclog_or_tty,
-    _cur_collection_pause_used_at_start_bytes, _g1->used(), _g1->capacity());
+                             _heap_used_bytes_before_gc,
+                             _g1->used(),
+                             _g1->capacity());
 }
 
-void G1CollectorPolicy::print_detailed_heap_transition() {
-    YoungList* young_list = _g1->young_list();
-    size_t eden_bytes = young_list->eden_used_bytes();
-    size_t survivor_bytes = young_list->survivor_used_bytes();
-    size_t used_before_gc = _cur_collection_pause_used_at_start_bytes;
-    size_t used = _g1->used();
-    size_t capacity = _g1->capacity();
-    size_t eden_capacity =
-      (_young_list_target_length * HeapRegion::GrainBytes) - survivor_bytes;
+void G1CollectorPolicy::print_detailed_heap_transition(bool full) {
+  YoungList* young_list = _g1->young_list();
 
-    gclog_or_tty->print_cr(
-      "   [Eden: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->"EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT") "
-      "Survivors: "EXT_SIZE_FORMAT"->"EXT_SIZE_FORMAT" "
-      "Heap: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->"
-      EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")]",
-      EXT_SIZE_PARAMS(_eden_bytes_before_gc),
-      EXT_SIZE_PARAMS(_prev_eden_capacity),
-      EXT_SIZE_PARAMS(eden_bytes),
-      EXT_SIZE_PARAMS(eden_capacity),
-      EXT_SIZE_PARAMS(_survivor_bytes_before_gc),
-      EXT_SIZE_PARAMS(survivor_bytes),
-      EXT_SIZE_PARAMS(used_before_gc),
-      EXT_SIZE_PARAMS(_capacity_before_gc),
-      EXT_SIZE_PARAMS(used),
-      EXT_SIZE_PARAMS(capacity));
+  size_t eden_used_bytes_after_gc = young_list->eden_used_bytes();
+  size_t survivor_used_bytes_after_gc = young_list->survivor_used_bytes();
+  size_t heap_used_bytes_after_gc = _g1->used();
+
+  size_t heap_capacity_bytes_after_gc = _g1->capacity();
+  size_t eden_capacity_bytes_after_gc =
+    (_young_list_target_length * HeapRegion::GrainBytes) - survivor_used_bytes_after_gc;
+
+  gclog_or_tty->print(
+    "   [Eden: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->"EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT") "
+    "Survivors: "EXT_SIZE_FORMAT"->"EXT_SIZE_FORMAT" "
+    "Heap: "EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")->"
+    EXT_SIZE_FORMAT"("EXT_SIZE_FORMAT")]",
+    EXT_SIZE_PARAMS(_eden_used_bytes_before_gc),
+    EXT_SIZE_PARAMS(_eden_capacity_bytes_before_gc),
+    EXT_SIZE_PARAMS(eden_used_bytes_after_gc),
+    EXT_SIZE_PARAMS(eden_capacity_bytes_after_gc),
+    EXT_SIZE_PARAMS(_survivor_used_bytes_before_gc),
+    EXT_SIZE_PARAMS(survivor_used_bytes_after_gc),
+    EXT_SIZE_PARAMS(_heap_used_bytes_before_gc),
+    EXT_SIZE_PARAMS(_heap_capacity_bytes_before_gc),
+    EXT_SIZE_PARAMS(heap_used_bytes_after_gc),
+    EXT_SIZE_PARAMS(heap_capacity_bytes_after_gc));
+
+  if (full) {
+    MetaspaceAux::print_metaspace_change(_metaspace_used_bytes_before_gc);
+  }
+
+  gclog_or_tty->cr();
 }
 
 void G1CollectorPolicy::adjust_concurrent_refinement(double update_rs_time,

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

@@ -175,7 +175,6 @@ private:
   CollectionSetChooser* _collectionSetChooser;
 
   double _full_collection_start_sec;
-  size_t _cur_collection_pause_used_at_start_bytes;
   uint   _cur_collection_pause_used_regions_at_start;
 
   // These exclude marking times.
@@ -194,7 +193,6 @@ private:
 
   uint _young_list_target_length;
   uint _young_list_fixed_length;
-  size_t _prev_eden_capacity; // used for logging
 
   // The max number of regions we can extend the eden by while the GC
   // locker is active. This should be >= _young_list_target_length;
@@ -693,11 +691,11 @@ public:
 
   // Records the information about the heap size for reporting in
   // print_detailed_heap_transition
-  void record_heap_size_info_at_start();
+  void record_heap_size_info_at_start(bool full);
 
   // Print heap sizing transition (with less and more detail).
   void print_heap_transition();
-  void print_detailed_heap_transition();
+  void print_detailed_heap_transition(bool full = false);
 
   void record_stop_world_start();
   void record_concurrent_pause();
@@ -861,9 +859,16 @@ private:
   uint _max_survivor_regions;
 
   // For reporting purposes.
-  size_t _eden_bytes_before_gc;
-  size_t _survivor_bytes_before_gc;
-  size_t _capacity_before_gc;
+  // The value of _heap_bytes_before_gc is also used to calculate
+  // the cost of copying.
+
+  size_t _eden_used_bytes_before_gc;         // Eden occupancy before GC
+  size_t _survivor_used_bytes_before_gc;     // Survivor occupancy before GC
+  size_t _heap_used_bytes_before_gc;         // Heap occupancy before GC
+  size_t _metaspace_used_bytes_before_gc;    // Metaspace occupancy before GC
+
+  size_t _eden_capacity_bytes_before_gc;     // Eden capacity before GC
+  size_t _heap_capacity_bytes_before_gc;     // Heap capacity before GC
 
   // The amount of survivor regions after a collection.
   uint _recorded_survivor_regions;

hotspot/test/gc/g1/TestPrintGCDetails.java

@@ -0,0 +1,57 @@
+/*
+ * Copyright (c) 2013, 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.
+ */
+
+/*
+ * @test TestPrintGCDetails
+ * @bug 8010738
+ * @summary Ensure that the PrintGCDetails for a full GC with G1 includes Metaspace.
+ * @key gc
+ * @key regression
+ * @library /testlibrary
+ */
+
+import com.oracle.java.testlibrary.ProcessTools;
+import com.oracle.java.testlibrary.OutputAnalyzer;
+
+public class TestPrintGCDetails {
+  public static void main(String[] args) throws Exception {
+
+    ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                              "-XX:+PrintGCDetails",
+                                                              SystemGCTest.class.getName());
+
+    OutputAnalyzer output = new OutputAnalyzer(pb.start());
+
+    System.out.println("Output:\n" + output.getOutput());
+
+    output.shouldContain("Metaspace");
+    output.shouldHaveExitValue(0);
+  }
+
+  static class SystemGCTest {
+    public static void main(String [] args) {
+      System.out.println("Calling System.gc()");
+      System.gc();
+    }
+  }
+}