changeset 7449:ac5d21fb6715

Improve summary output: include full-gc, final evacuation and final update-refs pauses, and concurrent mark timing. Only print heap regions when Verbose.
author Roman Kennke <rkennke@redhat.com>
date Fri, 16 Jan 2015 12:30:35 +0100
parents 5d8c71ac66b0
children 557818193d0e
files src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.cpp src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp src/share/vm/gc_implementation/shenandoah/shenandoahConcurrentMark.cpp src/share/vm/gc_implementation/shenandoah/shenandoahMarkCompact.cpp src/share/vm/gc_implementation/shenandoah/vm_operations_shenandoah.cpp
diffstat 5 files changed, 132 insertions(+), 1 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.cpp	Wed Jan 21 13:16:36 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.cpp	Fri Jan 16 12:30:35 2015 +0100
@@ -6,7 +6,12 @@
 private:
   NumberSeq _init_mark_ms;
   NumberSeq _final_mark_ms;
-  NumberSeq _concurrent_marking_times_ms;
+  NumberSeq _final_evac_ms;
+  NumberSeq _final_uprefs_ms;
+
+  NumberSeq _fullgc_ms;
+
+  NumberSeq _concurrent_mark_times_ms;
   NumberSeq _concurrent_evacuation_times_ms;
 
   NumberSeq _allocation_rate_bytes;
@@ -15,11 +20,18 @@
   double _init_mark_start;
   double _concurrent_mark_start;
   double _final_mark_start;
+  double _final_evac_start;
+  double _final_uprefs_start;
   double _concurrent_evacuation_start; 
+  double _fullgc_start; 
 
   int _init_mark_count;
   int _final_mark_count;
+  int _final_evac_count;
+  int _final_uprefs_count;
   int _concurrent_evacuation_count;
+  int _concurrent_mark_count;
+  int _fullgc_count;
 
   size_t _bytes_allocated_since_CM;
   size_t _bytes_reclaimed_this_cycle;
@@ -34,8 +46,14 @@
   void record_concurrent_mark_end();
   void record_final_mark_start();
   void record_final_mark_end();
+  void record_final_evacuation_start();
+  void record_final_evacuation_end();
+  void record_final_update_refs_start();
+  void record_final_update_refs_end();
   void record_concurrent_evacuation_start();
   void record_concurrent_evacuation_end();  
+  void record_fullgc_start();
+  void record_fullgc_end();
   void record_bytes_allocated(size_t bytes);
   void record_bytes_reclaimed(size_t bytes);
 
@@ -50,11 +68,18 @@
   _init_mark_start(0),
   _concurrent_mark_start(0),
   _final_mark_start(0),
+  _final_evac_start(0),
+  _final_uprefs_start(0),
   _concurrent_evacuation_start(0),
+  _fullgc_start(0),
   _bytes_allocated_since_CM(0),
   _bytes_reclaimed_this_cycle(0),
   _init_mark_count(0),
   _final_mark_count(0),
+  _final_evac_count(0),
+  _final_uprefs_count(0),
+  _fullgc_count(0),
+  _concurrent_mark_count(0),
   _concurrent_evacuation_count(0)
 {
   if (PrintGCDetails)
@@ -85,6 +110,29 @@
     tty->print_cr("PolicyPrint: FinalMark %d took %lf ms", _final_mark_count++, elapsed * 1000);
 }
 
+void ShenandoahHeuristics::record_final_evacuation_start() {
+  _final_evac_start = os::elapsedTime();
+}
+
+void ShenandoahHeuristics::record_final_evacuation_end() {
+  double elapsed = os::elapsedTime() - _final_evac_start;
+  _final_evac_ms.add(elapsed * 1000);
+  if (ShenandoahGCVerbose && PrintGCDetails) {
+    tty->print_cr("PolicyPrint: FinalEvacuation "INT32_FORMAT" took %lf ms", _final_evac_count++, elapsed * 1000);
+  }
+}
+
+void ShenandoahHeuristics::record_final_update_refs_start() { 
+  _final_uprefs_start = os::elapsedTime();
+}
+
+void ShenandoahHeuristics::record_final_update_refs_end()   { 
+  double elapsed = os::elapsedTime() - _final_uprefs_start;
+  _final_uprefs_ms.add(elapsed * 1000);
+  if (ShenandoahGCVerbose && PrintGCDetails)
+    tty->print_cr("PolicyPrint: FinalUpdateRefs "INT32_FORMAT" took %lf ms", _final_uprefs_count++, elapsed * 1000);
+}
+
 void ShenandoahHeuristics::record_concurrent_evacuation_start() { 
   _concurrent_evacuation_start = os::elapsedTime();
 }
@@ -97,6 +145,30 @@
 		  _concurrent_evacuation_count++, elapsed * 1000);
 }
 
+void ShenandoahHeuristics::record_concurrent_mark_start() { 
+  _concurrent_mark_start = os::elapsedTime();
+}
+
+void ShenandoahHeuristics::record_concurrent_mark_end()   { 
+  double elapsed = os::elapsedTime() - _concurrent_mark_start;
+  _concurrent_mark_times_ms.add(elapsed * 1000);
+  if (ShenandoahGCVerbose && PrintGCDetails)
+    tty->print_cr("PolicyPrint: Concurrent Marking "INT32_FORMAT" took %lf ms", 
+		  _concurrent_mark_count++, elapsed * 1000);
+}
+
+void ShenandoahHeuristics::record_fullgc_start() { 
+  _fullgc_start = os::elapsedTime();
+}
+
+void ShenandoahHeuristics::record_fullgc_end()   { 
+  double elapsed = os::elapsedTime() - _fullgc_start;
+  _fullgc_ms.add(elapsed * 1000);
+  if (ShenandoahGCVerbose && PrintGCDetails)
+    tty->print_cr("PolicyPrint: Full GC "INT32_FORMAT" took %lf ms", 
+		  _fullgc_count++, elapsed * 1000);
+}
+
 void ShenandoahHeuristics::record_bytes_allocated(size_t bytes) {
   _bytes_allocated_since_CM = bytes;
   _allocation_rate_bytes.add(bytes);
@@ -511,6 +583,22 @@
   _heuristics->record_final_mark_end();
 }
 
+void ShenandoahCollectorPolicy::record_final_evacuation_start() { 
+  _heuristics->record_final_evacuation_start();
+}
+
+void ShenandoahCollectorPolicy::record_final_evacuation_end() { 
+  _heuristics->record_final_evacuation_end();
+}
+
+void ShenandoahCollectorPolicy::record_final_update_refs_start() { 
+  _heuristics->record_final_update_refs_start();
+}
+
+void ShenandoahCollectorPolicy::record_final_update_refs_end() { 
+  _heuristics->record_final_update_refs_end();
+}
+
 void ShenandoahCollectorPolicy::record_concurrent_evacuation_start() { 
     _heuristics->record_concurrent_evacuation_start();
 }
@@ -519,6 +607,22 @@
     _heuristics->record_concurrent_evacuation_end();
 }
 
+void ShenandoahCollectorPolicy::record_concurrent_mark_start() { 
+    _heuristics->record_concurrent_mark_start();
+}
+
+void ShenandoahCollectorPolicy::record_concurrent_mark_end()   { 
+    _heuristics->record_concurrent_mark_end();
+}
+
+void ShenandoahCollectorPolicy::record_fullgc_start() { 
+    _heuristics->record_fullgc_start();
+}
+
+void ShenandoahCollectorPolicy::record_fullgc_end()   { 
+    _heuristics->record_fullgc_end();
+}
+
 void ShenandoahCollectorPolicy::record_bytes_allocated(size_t bytes) {
   _heuristics->record_bytes_allocated(bytes);
 }
@@ -560,6 +664,12 @@
 void ShenandoahHeuristics::print_tracing_info() {
   print_summary_sd("Initial Mark Pauses", &_init_mark_ms);
   print_summary_sd("Final Mark Pauses", &_final_mark_ms);
+  print_summary_sd("Final Evacuation Pauses", &_final_evac_ms);
+  print_summary_sd("Final Update Refs Pauses", &_final_uprefs_ms);
+  print_summary_sd("Concurrent Marking Times", 
+		   &_concurrent_mark_times_ms);
   print_summary_sd("Concurrent Evacuation Times", 
 		   &_concurrent_evacuation_times_ms);
+  print_summary_sd("Full GC Times", 
+		   &_fullgc_ms);
 }
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp	Wed Jan 21 13:16:36 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp	Fri Jan 16 12:30:35 2015 +0100
@@ -43,8 +43,14 @@
   void record_concurrent_mark_end();
   void record_final_mark_start();
   void record_final_mark_end();
+  void record_final_evacuation_start();
+  void record_final_evacuation_end();
+  void record_final_update_refs_start();
+  void record_final_update_refs_end();
   void record_concurrent_evacuation_start();
   void record_concurrent_evacuation_end();
+  void record_fullgc_start();
+  void record_fullgc_end();
   void record_bytes_allocated(size_t bytes);
   void record_bytes_reclaimed(size_t bytes);
   bool should_start_concurrent_mark(size_t used, size_t capacity);
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahConcurrentMark.cpp	Wed Jan 21 13:16:36 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahConcurrentMark.cpp	Fri Jan 16 12:30:35 2015 +0100
@@ -386,7 +386,11 @@
     tty->print_cr("STOPPING THE WORLD: before marking");
     tty->print_cr("Starting markFromRoots");
   }
+
   ShenandoahHeap* sh = (ShenandoahHeap *) Universe::heap();
+
+  sh->shenandoahPolicy()->record_concurrent_mark_start();
+
   uint max_workers = full_gc ? _max_worker_id : _max_conc_worker_id;
   ParallelTaskTerminator terminator(max_workers, _task_queues);
   ReferenceProcessor* rp = sh->ref_processor_cm();
@@ -410,6 +414,7 @@
     TASKQUEUE_STATS_ONLY(reset_taskqueue_stats());
   }
 
+  sh->shenandoahPolicy()->record_concurrent_mark_end();
 }
 
 class FinishDrainSATBBuffersTask : public AbstractGangTask {
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahMarkCompact.cpp	Wed Jan 21 13:16:36 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahMarkCompact.cpp	Fri Jan 16 12:30:35 2015 +0100
@@ -31,6 +31,8 @@
   assert(!_heap->is_evacuation_in_progress(), "can't do full-GC while evacuation is in progress");
   assert(!_heap->is_update_references_in_progress(), "can't do full-GC while updating of references is in progress");
 
+  _heap->shenandoahPolicy()->record_fullgc_start();
+
   if (ShenandoahVerify) {
     // Full GC should only be called between regular concurrent cycles, therefore
     // those verifications should be valid.
@@ -66,6 +68,8 @@
   }
 
   _heap->reset_mark_bitmap();
+
+  _heap->shenandoahPolicy()->record_fullgc_end();
 }
 
 void ShenandoahMarkCompact::phase1_mark_heap() {
--- a/src/share/vm/gc_implementation/shenandoah/vm_operations_shenandoah.cpp	Wed Jan 21 13:16:36 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/vm_operations_shenandoah.cpp	Fri Jan 16 12:30:35 2015 +0100
@@ -202,6 +202,9 @@
     tty->print("vm_ShenandoahUpdateRootRefs\n");
 
   ShenandoahHeap *sh = ShenandoahHeap::heap();
+
+  sh->shenandoahPolicy()->record_final_update_refs_start();
+
   sh->update_roots();
 
   if (ShenandoahVerify) {
@@ -216,6 +219,7 @@
 
   sh->reset_mark_bitmap();
 
+  sh->shenandoahPolicy()->record_final_update_refs_end();
 }
 
 VM_Operation::VMOp_Type VM_ShenandoahUpdateRefs::type() const {
@@ -231,7 +235,9 @@
     tty->print("vm_ShenandoahUpdateRefs\n");
 
   ShenandoahHeap *sh = ShenandoahHeap::heap();
+  sh->shenandoahPolicy()->record_final_evacuation_start();
   sh->set_evacuation_in_progress(false);
   sh->prepare_for_update_references();
   assert(ShenandoahConcurrentUpdateRefs, "only do this when concurrent update references is turned on");
+  sh->shenandoahPolicy()->record_final_evacuation_end();
 }