changeset 9584:85a63e83293f

8060017: G1: Report heap sizing time Summary: Report heap expansion time done on VM thread after collection. Previously this was included in "Other" time. Reviewed-by: mgerdin, tschatzl
author ecaspole
date Tue, 20 Oct 2015 14:01:49 -0400
parents 9b74c5f1b10e
children dcf365644bef
files src/share/vm/gc/g1/g1CollectedHeap.cpp src/share/vm/gc/g1/g1CollectedHeap.hpp src/share/vm/gc/g1/g1GCPhaseTimes.cpp src/share/vm/gc/g1/g1GCPhaseTimes.hpp test/gc/g1/TestGCLogMessages.java
diffstat 5 files changed, 25 insertions(+), 3 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/gc/g1/g1CollectedHeap.cpp	Tue Oct 20 14:00:00 2015 +0200
+++ b/src/share/vm/gc/g1/g1CollectedHeap.cpp	Tue Oct 20 14:01:49 2015 -0400
@@ -1712,7 +1712,7 @@
   return NULL;
 }
 
-bool G1CollectedHeap::expand(size_t expand_bytes) {
+bool G1CollectedHeap::expand(size_t expand_bytes, double* expand_time_ms) {
   size_t aligned_expand_bytes = ReservedSpace::page_align_size_up(expand_bytes);
   aligned_expand_bytes = align_size_up(aligned_expand_bytes,
                                        HeapRegion::GrainBytes);
@@ -1729,10 +1729,14 @@
     return false;
   }
 
+  double expand_heap_start_time_sec = os::elapsedTime();
   uint regions_to_expand = (uint)(aligned_expand_bytes / HeapRegion::GrainBytes);
   assert(regions_to_expand > 0, "Must expand by at least one region");
 
   uint expanded_by = _hrm.expand_by(regions_to_expand);
+  if (expand_time_ms != NULL) {
+    *expand_time_ms = (os::elapsedTime() - expand_heap_start_time_sec) * MILLIUNITS;
+  }
 
   if (expanded_by > 0) {
     size_t actual_expand_bytes = expanded_by * HeapRegion::GrainBytes;
@@ -3990,9 +3994,11 @@
             size_t bytes_before = capacity();
             // No need for an ergo verbose message here,
             // expansion_amount() does this when it returns a value > 0.
-            if (!expand(expand_bytes)) {
+            double expand_ms;
+            if (!expand(expand_bytes, &expand_ms)) {
               // We failed to expand the heap. Cannot do anything about it.
             }
+            g1_policy()->phase_times()->record_expand_heap_time(expand_ms);
           }
         }
 
--- a/src/share/vm/gc/g1/g1CollectedHeap.hpp	Tue Oct 20 14:00:00 2015 +0200
+++ b/src/share/vm/gc/g1/g1CollectedHeap.hpp	Tue Oct 20 14:01:49 2015 -0400
@@ -538,7 +538,7 @@
   // Returns true if the heap was expanded by the requested amount;
   // false otherwise.
   // (Rounds up to a HeapRegion boundary.)
-  bool expand(size_t expand_bytes);
+  bool expand(size_t expand_bytes, double* expand_time_ms = NULL);
 
   // Returns the PLAB statistics for a given destination.
   inline G1EvacStats* alloc_buffer_stats(InCSetState dest);
--- a/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Tue Oct 20 14:00:00 2015 +0200
+++ b/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Tue Oct 20 14:01:49 2015 -0400
@@ -298,6 +298,7 @@
   assert(active_gc_threads > 0, "The number of threads must be > 0");
   assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
   _active_gc_threads = active_gc_threads;
+  _cur_expand_heap_time_ms = 0.0;
 
   for (int i = 0; i < GCParPhasesSentinel; i++) {
     _gc_par_phases[i]->reset();
@@ -363,6 +364,9 @@
     // current value of "other time"
     misc_time_ms += _cur_clear_ct_time_ms;
 
+    // Remove expand heap time from "other time"
+    misc_time_ms += _cur_expand_heap_time_ms;
+
     return misc_time_ms;
 }
 
@@ -536,6 +540,8 @@
     }
   }
   print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
+  print_stats(1, "Expand Heap After Collection", _cur_expand_heap_time_ms);
+
   double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
   print_stats(1, "Other", misc_time_ms);
   if (_cur_verify_before_time_ms > 0.0) {
--- a/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Tue Oct 20 14:00:00 2015 +0200
+++ b/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Tue Oct 20 14:01:49 2015 -0400
@@ -92,6 +92,7 @@
   double _cur_string_dedup_fixup_time_ms;
 
   double _cur_clear_ct_time_ms;
+  double _cur_expand_heap_time_ms;
   double _cur_ref_proc_time_ms;
   double _cur_ref_enq_time_ms;
 
@@ -155,6 +156,10 @@
     _cur_clear_ct_time_ms = ms;
   }
 
+  void record_expand_heap_time(double ms) {
+    _cur_expand_heap_time_ms = ms;
+  }
+
   void record_par_time(double ms) {
     _cur_collection_par_time_ms = ms;
   }
@@ -252,6 +257,10 @@
     return _cur_clear_ct_time_ms;
   }
 
+  double cur_expand_heap_time_ms() {
+    return _cur_expand_heap_time_ms;
+  }
+
   double root_region_scan_wait_time_ms() {
     return _root_region_scan_wait_time_ms;
   }
--- a/test/gc/g1/TestGCLogMessages.java	Tue Oct 20 14:00:00 2015 +0200
+++ b/test/gc/g1/TestGCLogMessages.java	Tue Oct 20 14:01:49 2015 -0400
@@ -79,6 +79,7 @@
         // Misc Top-level
         new LogMessageWithLevel("Code Root Purge", Level.FINER),
         new LogMessageWithLevel("String Dedup Fixup", Level.FINER),
+        new LogMessageWithLevel("Expand Heap After Collection", Level.FINER),
         // Free CSet
         new LogMessageWithLevel("Young Free CSet", Level.FINEST),
         new LogMessageWithLevel("Non-Young Free CSet", Level.FINEST),