8010780: G1: Eden occupancy/capacity output wrong after a full GC

Summary: Move the calculation and recording of eden capacity to the start of a GC and print a detailed heap transition for full GCs.
Reviewed-by: tschatzl, jmasa

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

 /*
- * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2001, 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
@@ -1322,6 +1322,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
     gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
     TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
 
+    {
       TraceTime t(GCCauseString("Full GC", gc_cause()), G1Log::fine(), true, gclog_or_tty);
       TraceCollectorStats tcs(g1mm()->full_collection_counters());
       TraceMemoryManagerStats tms(true /* fullGC */, gc_cause());
@@ -1347,7 +1348,6 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
       increment_total_collections(true /* full gc */);
       increment_old_marking_cycles_started();
 
-    size_t g1h_prev_used = used();
       assert(used() == recalculate_used(), "Should be equal");
 
       verify_before_gc();
@@ -1494,43 +1494,24 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
         heap_region_iterate(&rebuild_rs);
       }
 
-    if (G1Log::fine()) {
-      print_size_transition(gclog_or_tty, g1h_prev_used, used(), capacity());
-    }
-
       if (true) { // FIXME
         MetaspaceGC::compute_new_size();
       }
 
-    // Start a new incremental collection set for the next pause
-    assert(g1_policy()->collection_set() == NULL, "must be");
-    g1_policy()->start_incremental_cset_building();
-
-    // Clear the _cset_fast_test bitmap in anticipation of adding
-    // regions to the incremental collection set for the next
-    // evacuation pause.
-    clear_cset_fast_test();
-
-    init_mutator_alloc_region();
-
-    double end = os::elapsedTime();
-    g1_policy()->record_full_collection_end();
-
 #ifdef TRACESPINNING
       ParallelTaskTerminator::print_termination_counts();
 #endif
 
-    gc_epilogue(true);
-
       // Discard all rset updates
       JavaThread::dirty_card_queue_set().abandon_logs();
       assert(!G1DeferredRSUpdate
-           || (G1DeferredRSUpdate && (dirty_card_queue_set().completed_buffers_num() == 0)), "Should not be any");
+             || (G1DeferredRSUpdate &&
+                (dirty_card_queue_set().completed_buffers_num() == 0)), "Should not be any");
 
       _young_list->reset_sampled_info();
       // At this point there should be no regions in the
       // entire heap tagged as young.
-    assert( check_young_list_empty(true /* check_heap */),
+      assert(check_young_list_empty(true /* check_heap */),
              "young list should be empty at this point");
 
       // Update the number of full collections that have been completed.
@@ -1539,16 +1520,41 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
       _hrs.verify_optional();
       verify_region_sets_optional();
 
-    print_heap_after_gc();
+      // Start a new incremental collection set for the next pause
+      assert(g1_policy()->collection_set() == NULL, "must be");
+      g1_policy()->start_incremental_cset_building();
+
+      // Clear the _cset_fast_test bitmap in anticipation of adding
+      // regions to the incremental collection set for the next
+      // evacuation pause.
+      clear_cset_fast_test();
+
+      init_mutator_alloc_region();
+
+      double end = os::elapsedTime();
+      g1_policy()->record_full_collection_end();
+
+      if (G1Log::fine()) {
+        g1_policy()->print_heap_transition();
+      }
 
       // We must call G1MonitoringSupport::update_sizes() in the same scoping level
       // as an active TraceMemoryManagerStats object (i.e. before the destructor for the
       // TraceMemoryManagerStats is called) so that the G1 memory pools are updated
       // before any GC notifications are raised.
       g1mm()->update_sizes();
+
+      gc_epilogue(true);
     }
 
+    if (G1Log::finer()) {
+      g1_policy()->print_detailed_heap_transition();
+    }
+
+    print_heap_after_gc();
+
     post_full_gc_dump();
+  }
 
   return true;
 }
@@ -3829,7 +3835,6 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
         // The elapsed time induced by the start time below deliberately elides
         // the possible verification above.
         double sample_start_time_sec = os::elapsedTime();
-        size_t start_used_bytes = used();
 
 #if YOUNG_LIST_VERBOSE
         gclog_or_tty->print_cr("\nBefore recording pause start.\nYoung_list:");
@@ -3837,8 +3842,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
         g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty);
 #endif // YOUNG_LIST_VERBOSE
 
-        g1_policy()->record_collection_pause_start(sample_start_time_sec,
-                                                   start_used_bytes);
+        g1_policy()->record_collection_pause_start(sample_start_time_sec);
 
         double scan_wait_start = os::elapsedTime();
         // We have to wait until the CM threads finish scanning the

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

 /*
- * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2001, 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
@@ -406,7 +406,6 @@ void G1CollectorPolicy::init() {
   }
   _free_regions_at_end_of_collection = _g1->free_regions();
   update_young_list_target_length();
-  _prev_eden_capacity = _young_list_target_length * HeapRegion::GrainBytes;
 
   // We may immediately start allocating regions and placing them on the
   // collection set list. Initialize the per-collection set info
@@ -746,6 +745,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();
   // Release the future to-space so that it is available for compaction into.
   _g1->set_full_collection();
 }
@@ -788,8 +788,7 @@ void G1CollectorPolicy::record_stop_world_start() {
   _stop_world_start = os::elapsedTime();
 }
 
-void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
-                                                      size_t start_used) {
+void G1CollectorPolicy::record_collection_pause_start(double start_time_sec) {
   // We only need to do this here as the policy will only be applied
   // to the GC we're about to start. so, no point is calculating this
   // every time we calculate / recalculate the target young length.
@@ -803,19 +802,14 @@ 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();
+
   phase_times()->record_cur_collection_start_sec(start_time_sec);
-  _cur_collection_pause_used_at_start_bytes = start_used;
-  _cur_collection_pause_used_regions_at_start = _g1->used_regions();
   _pending_cards = _g1->pending_card_num();
 
   _collection_set_bytes_used_before = 0;
   _bytes_copied_during_gc = 0;
 
-  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();
-
   _last_gc_was_young = false;
 
   // do that for any other surv rate groups
@@ -1153,6 +1147,21 @@ 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() {
+  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();
+  _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;
+
+  _prev_eden_capacity = eden_capacity_before_gc;
+}
+
 void G1CollectorPolicy::print_heap_transition() {
   _g1->print_size_transition(gclog_or_tty,
     _cur_collection_pause_used_at_start_bytes, _g1->used(), _g1->capacity());
@@ -1183,8 +1192,6 @@ void G1CollectorPolicy::print_detailed_heap_transition() {
       EXT_SIZE_PARAMS(_capacity_before_gc),
       EXT_SIZE_PARAMS(used),
       EXT_SIZE_PARAMS(capacity));
-
-    _prev_eden_capacity = eden_capacity;
 }
 
 void G1CollectorPolicy::adjust_concurrent_refinement(double update_rs_time,

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

 /*
- * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2001, 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
@@ -671,34 +671,36 @@ public:
 
   bool need_to_start_conc_mark(const char* source, size_t alloc_word_size = 0);
 
-  // Update the heuristic info to record a collection pause of the given
-  // start time, where the given number of bytes were used at the start.
-  // This may involve changing the desired size of a collection set.
+  // Record the start and end of an evacuation pause.
+  void record_collection_pause_start(double start_time_sec);
+  void record_collection_pause_end(double pause_time_ms);
 
-  void record_stop_world_start();
-
-  void record_collection_pause_start(double start_time_sec, size_t start_used);
+  // Record the start and end of a full collection.
+  void record_full_collection_start();
+  void record_full_collection_end();
 
   // Must currently be called while the world is stopped.
-  void record_concurrent_mark_init_end(double
-                                           mark_init_elapsed_time_ms);
+  void record_concurrent_mark_init_end(double mark_init_elapsed_time_ms);
 
+  // Record start and end of remark.
   void record_concurrent_mark_remark_start();
   void record_concurrent_mark_remark_end();
 
+  // Record start, end, and completion of cleanup.
   void record_concurrent_mark_cleanup_start();
   void record_concurrent_mark_cleanup_end(int no_of_gc_threads);
   void record_concurrent_mark_cleanup_completed();
 
-  void record_concurrent_pause();
+  // Records the information about the heap size for reporting in
+  // print_detailed_heap_transition
+  void record_heap_size_info_at_start();
 
-  void record_collection_pause_end(double pause_time);
+  // Print heap sizing transition (with less and more detail).
   void print_heap_transition();
   void print_detailed_heap_transition();
 
-  // Record the fact that a full collection occurred.
-  void record_full_collection_start();
-  void record_full_collection_end();
+  void record_stop_world_start();
+  void record_concurrent_pause();
 
   // Record how much space we copied during a GC. This is typically
   // called when a GC alloc region is being retired.