Mercurial > hg > shenandoah-preopenjdk-archive > openjdk8 > hotspot

changeset 7465:2868d01310a4

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
More detailed timing summary.
author Roman Kennke <rkennke@redhat.com>
date Thu, 12 Feb 2015 17:33:38 +0100
parents cc302a9b1bdc
children 8a704517c74e
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/shenandoahHeap.cpp src/share/vm/gc_implementation/shenandoah/vm_operations_shenandoah.cpp
diffstat 5 files changed, 105 insertions(+), 19 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.cpp	Wed Feb 11 23:46:45 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.cpp	Thu Feb 12 17:33:38 2015 +0100
@@ -365,8 +365,17 @@
 ShenandoahCollectorPolicy::ShenandoahCollectorPolicy() {
   initialize_all();
 
+  _user_requested_gcs = 0;
+
   _phase_names[init_mark] = "InitMark";
   _phase_names[final_mark] = "FinalMark";
+  _phase_names[final_mark] = "RescanRoots";
+  _phase_names[final_mark] = "DrainSATB";
+  _phase_names[final_mark] = "DrainOverflow";
+  _phase_names[final_mark] = "DrainQueues";
+  _phase_names[final_mark] = "WeakRefs";
+  _phase_names[final_mark] = "PrepareEvac";
+  _phase_names[final_mark] = "InitEvac";
   _phase_names[final_evac] = "FinalEvacuation";
   _phase_names[final_uprefs] = "FinalUpdateRefs";
 
@@ -467,6 +476,10 @@
   _heuristics->record_bytes_reclaimed(bytes);
 }
 
+void ShenandoahCollectorPolicy::record_user_requested_gc() {
+  _user_requested_gcs++;
+}
+
 bool ShenandoahCollectorPolicy::should_start_concurrent_mark(size_t used,
 							     size_t capacity) {
   ShenandoahHeap* heap = ShenandoahHeap::heap();
@@ -481,30 +494,61 @@
 }
 
 void ShenandoahCollectorPolicy::print_tracing_info() {
-  print_summary_sd("Initial Mark Pauses", &(_timing_data[init_mark]._ms));
-  print_summary_sd("Final Mark Pauses", &(_timing_data[final_mark]._ms));
-  print_summary_sd("Final Evacuation Pauses", &(_timing_data[final_evac]._ms));
-  print_summary_sd("Final Update Refs Pauses", &(_timing_data[final_uprefs]._ms));
-  print_summary_sd("  Update roots", &(_timing_data[update_roots]._ms));
-  print_summary_sd("  Recycle regions", &(_timing_data[recycle_regions]._ms));
+  print_summary_sd("Initial Mark Pauses", 0, &(_timing_data[init_mark]._ms));
+  print_summary_sd("Final Mark Pauses", 0, &(_timing_data[final_mark]._ms));
+
+  print_summary_sd("Rescan Roots", 2, &(_timing_data[rescan_roots]._ms));
+  print_summary_sd("Drain SATB", 2, &(_timing_data[drain_satb]._ms));
+  print_summary_sd("Drain Overflow", 2, &(_timing_data[drain_overflow]._ms));
+  print_summary_sd("Drain Queues", 2, &(_timing_data[drain_queues]._ms));
+  print_summary_sd("Weak References", 2, &(_timing_data[weakrefs]._ms));
+  print_summary_sd("Prepare Evacuation", 2, &(_timing_data[prepare_evac]._ms));
+  print_summary_sd("Initial Evacuation", 2, &(_timing_data[init_evac]._ms));
+
+  print_summary_sd("Final Evacuation Pauses", 0, &(_timing_data[final_evac]._ms));
+  print_summary_sd("Final Update Refs Pauses", 0, &(_timing_data[final_uprefs]._ms));
+  print_summary_sd("Update roots", 2, &(_timing_data[update_roots]._ms));
+  print_summary_sd("Recycle regions", 2, &(_timing_data[recycle_regions]._ms));
   if (! ShenandoahUpdateRefsEarly) {
-    print_summary_sd("  Reset bitmaps", &(_timing_data[reset_bitmaps]._ms));
+    print_summary_sd("Reset bitmaps", 2, &(_timing_data[reset_bitmaps]._ms));
   }
-  print_summary_sd("  Resize TLABs", &(_timing_data[resize_tlabs]._ms));
+  print_summary_sd("Resize TLABs", 2, &(_timing_data[resize_tlabs]._ms));
+  gclog_or_tty->print_cr(" ");
+  print_summary_sd("Concurrent Marking Times", 0, &(_timing_data[conc_mark]._ms));
+  print_summary_sd("Concurrent Evacuation Times", 0, &(_timing_data[conc_evac]._ms));
+  print_summary_sd("Full GC Times", 0, &(_timing_data[full_gc]._ms));
+
+  gclog_or_tty->print_cr("User requested GCs: "SIZE_FORMAT, _user_requested_gcs);
+
   gclog_or_tty->print_cr(" ");
-  print_summary_sd("Concurrent Marking Times", &(_timing_data[conc_mark]._ms));
-  print_summary_sd("Concurrent Evacuation Times", &(_timing_data[conc_evac]._ms));
-  print_summary_sd("Full GC Times", &(_timing_data[full_gc]._ms));
+  double total_sum = _timing_data[init_mark]._ms.sum() +
+    _timing_data[final_mark]._ms.sum() +
+    _timing_data[final_evac]._ms.sum() +
+    _timing_data[final_uprefs]._ms.sum();
+  double total_avg = (_timing_data[init_mark]._ms.avg() +
+                      _timing_data[final_mark]._ms.avg() +
+                      _timing_data[final_evac]._ms.avg() +
+                      _timing_data[final_uprefs]._ms.avg()) / 4.0;
+  double total_max = MAX2(
+                          MAX2(
+                               MAX2(_timing_data[init_mark]._ms.maximum(),
+                                    _timing_data[final_mark]._ms.maximum()),
+                               _timing_data[final_evac]._ms.maximum()),
+                          _timing_data[final_uprefs]._ms.maximum());
+
+  gclog_or_tty->print_cr("%-27s = %8.2lf s, avg = %8.2lf ms, max = %8.2lf ms",
+                         "Total", total_sum / 1000.0, total_avg, total_max);
+
 }
 
-void ShenandoahCollectorPolicy::print_summary(const char* str, const NumberSeq* seq)  {
+void ShenandoahCollectorPolicy::print_summary_sd(const char* str, uint indent, const NumberSeq* seq) {
+
+
   double sum = seq->sum();
+  for (uint i = 0; i < indent; i++) gclog_or_tty->print(" ");
   gclog_or_tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)",
                          str, sum / 1000.0, seq->avg());
-}
-
-void ShenandoahCollectorPolicy::print_summary_sd(const char* str, const NumberSeq* seq) {
-  print_summary(str, seq);
+  for (uint i = 0; i < indent; i++) gclog_or_tty->print(" ");
   gclog_or_tty->print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
                          seq->num(), seq->sd(), seq->maximum());
 }
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp	Wed Feb 11 23:46:45 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp	Thu Feb 12 17:33:38 2015 +0100
@@ -19,6 +19,14 @@
   enum TimingPhase {
     init_mark,
     final_mark,
+      rescan_roots,
+      drain_satb,
+      drain_overflow,
+      drain_queues,
+      weakrefs,
+      prepare_evac,
+      init_evac,
+
     final_evac,
     final_uprefs,
       update_roots,
@@ -43,6 +51,8 @@
   TimingData _timing_data[_num_phases];
   const char* _phase_names[_num_phases];
 
+  size_t _user_requested_gcs;
+
   ShenandoahHeap* _pgc;
   ShenandoahHeuristics* _heuristics;
 
@@ -70,6 +80,8 @@
   void record_phase_start(TimingPhase phase);
   void record_phase_end(TimingPhase phase);
 
+  void record_user_requested_gc();
+
   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);
@@ -80,8 +92,7 @@
   void print_tracing_info();
 
 private:
-  void print_summary(const char* str, const NumberSeq* seq);
-  void print_summary_sd(const char* str, const NumberSeq* seq);
+  void print_summary_sd(const char* str, uint indent, const NumberSeq* seq);
 };
 
 
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahConcurrentMark.cpp	Wed Feb 11 23:46:45 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahConcurrentMark.cpp	Thu Feb 12 17:33:38 2015 +0100
@@ -440,19 +440,30 @@
 
   // Trace any (new) unmarked root references.
   if (! full_gc) {
+    sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::rescan_roots);
     prepare_unmarked_root_objs();
+    sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::rescan_roots);
   }
 
   {
+    if (! full_gc) {
+      sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::drain_satb);
+    }
     ParallelTaskTerminator terminator(_max_worker_id, _task_queues);
     ShenandoahHeap::StrongRootsScope srs(sh);
     // drain_satb_buffers(0, true);
     FinishDrainSATBBuffersTask drain_satb_buffers(this, &terminator);
     sh->workers()->set_active_workers(_max_worker_id);
     sh->workers()->run_task(&drain_satb_buffers);
+    if (! full_gc) {
+      sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::drain_satb);
+    }
   }
 
   // Also drain our overflow queue.
+  if (! full_gc) {
+    sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::drain_overflow);
+  }
   ShenandoahMarkRefsClosure cl1(0);
   ShenandoahMarkRefsNoUpdateClosure cl2(0);
   ExtendedOopClosure* cl;
@@ -467,13 +478,22 @@
     obj->oop_iterate(cl);
     obj = _overflow_queue->pop();
   }
+  if (! full_gc) {
+    sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::drain_overflow);
+  }
 
   // Finally mark everything else we've got in our queues during the previous steps.
   {
+    if (! full_gc) {
+      sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::drain_queues);
+    }
     ParallelTaskTerminator terminator(_max_worker_id, _task_queues);
     SCMConcurrentMarkingTask markingTask = SCMConcurrentMarkingTask(this, &terminator, !ShenandoahUpdateRefsEarly);
     sh->workers()->set_active_workers(_max_worker_id);
     sh->workers()->run_task(&markingTask);
+    if (! full_gc) {
+      sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::drain_queues);
+    }
   }
 
 #ifdef ASSERT
@@ -483,7 +503,13 @@
 #endif
 
   // When we're done marking everything, we process weak references.
+  if (! full_gc) {
+    sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::weakrefs);
+  }
   weak_refs_work();
+  if (! full_gc) {
+    sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::weakrefs);
+  }
 
 #ifdef ASSERT
   for (int i = 0; i < sh->max_workers(); i++) {
--- a/src/share/vm/gc_implementation/shenandoah/shenandoahHeap.cpp	Wed Feb 11 23:46:45 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/shenandoahHeap.cpp	Thu Feb 12 17:33:38 2015 +0100
@@ -1547,6 +1547,7 @@
       if (ShenandoahTraceFullGC) {
         gclog_or_tty->print_cr("Shenandoah-full-gc: requested full GC");
       }
+      shenandoahPolicy()->record_user_requested_gc();
       _concurrent_gc_thread->do_full_gc();
     }
   } else if (cause == GCCause::_allocation_failure) {
--- a/src/share/vm/gc_implementation/shenandoah/vm_operations_shenandoah.cpp	Wed Feb 11 23:46:45 2015 +0100
+++ b/src/share/vm/gc_implementation/shenandoah/vm_operations_shenandoah.cpp	Thu Feb 12 17:33:38 2015 +0100
@@ -103,17 +103,21 @@
   sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::final_mark);
   sh->concurrentMark()->finish_mark_from_roots();
   sh->stop_concurrent_marking();
-  sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::final_mark);
 
+  sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::prepare_evac);
   sh->prepare_for_concurrent_evacuation();
   sh->set_evacuation_in_progress(true);
+  sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::prepare_evac);
 
   if (! ShenandoahConcurrentEvacuation) {
     VM_ShenandoahEvacuation evacuation;
     evacuation.doit();
   } else {
+    sh->shenandoahPolicy()->record_phase_start(ShenandoahCollectorPolicy::init_evac);
     sh->evacuate_and_update_roots();
+    sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::init_evac);
   }
+  sh->shenandoahPolicy()->record_phase_end(ShenandoahCollectorPolicy::final_mark);
 }
 
 VM_Operation::VMOp_Type VM_ShenandoahStartEvacuation::type() const {