1 /*
   2  * Copyright (c) 2017, 2018, Red Hat, Inc. All rights reserved.
   3  *
   4  * This code is free software; you can redistribute it and/or modify it
   5  * under the terms of the GNU General Public License version 2 only, as
   6  * published by the Free Software Foundation.
   7  *
   8  * This code is distributed in the hope that it will be useful, but WITHOUT
   9  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  10  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  11  * version 2 for more details (a copy is included in the LICENSE file that
  12  * accompanied this code).
  13  *
  14  * You should have received a copy of the GNU General Public License version
  15  * 2 along with this work; if not, write to the Free Software Foundation,
  16  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  17  *
  18  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  19  * or visit www.oracle.com if you need additional information or have any
  20  * questions.
  21  *
  22  */
  23 
  24 #include "precompiled.hpp"
  25 
  26 #include "gc_implementation/shenandoah/shenandoahCollectorPolicy.hpp"
  27 #include "gc_implementation/shenandoah/shenandoahPhaseTimings.hpp"
  28 #include "gc_implementation/shenandoah/shenandoahHeap.hpp"
  29 #include "gc_implementation/shenandoah/shenandoahWorkerDataArray.hpp"
  30 #include "gc_implementation/shenandoah/shenandoahHeuristics.hpp"
  31 #include "gc_implementation/shenandoah/shenandoahUtils.hpp"
  32 #include "utilities/ostream.hpp"
  33 
  34 #define GC_PHASE_DECLARE_NAME(type, title) \
  35   title,
  36 
  37 const char* ShenandoahPhaseTimings::_phase_names[] = {
  38         SHENANDOAH_GC_PHASE_DO(GC_PHASE_DECLARE_NAME)
  39 };
  40 
  41 #undef GC_PHASE_DECLARE_NAME
  42 
  43 ShenandoahPhaseTimings::ShenandoahPhaseTimings() : _policy(NULL) {
  44   uint max_workers = (uint)MAX2(ConcGCThreads, ParallelGCThreads);
  45   _worker_times = new ShenandoahWorkerTimings(max_workers);
  46   _termination_times = new ShenandoahTerminationTimings(max_workers);
  47   _policy = ShenandoahHeap::heap()->shenandoah_policy();
  48   assert(_policy != NULL, "Can not be NULL");
  49 }
  50 
  51 void ShenandoahPhaseTimings::record_phase_start(Phase phase) {
  52   _timing_data[phase]._start = os::elapsedTime();
  53 }
  54 
  55 void ShenandoahPhaseTimings::record_phase_end(Phase phase) {
  56   assert(_policy != NULL, "Not yet initialized");
  57   double end = os::elapsedTime();
  58   double elapsed = end - _timing_data[phase]._start;
  59   if (!_policy->is_at_shutdown()) {
  60     _timing_data[phase]._secs.add(elapsed);
  61   }
  62   ShenandoahHeap::heap()->heuristics()->record_phase_time(phase, elapsed);
  63 }
  64 
  65 void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time) {
  66   assert(_policy != NULL, "Not yet initialized");
  67   if (!_policy->is_at_shutdown()) {
  68     _timing_data[phase]._secs.add(time);
  69   }
  70 }
  71 
  72 void ShenandoahPhaseTimings::record_workers_start(Phase phase) {
  73   for (uint i = 0; i < GCParPhasesSentinel; i++) {
  74     _worker_times->reset(i);
  75   }
  76 }
  77 
  78 void ShenandoahPhaseTimings::record_workers_end(Phase phase) {
  79   if (_policy->is_at_shutdown()) {
  80     // Do not record the past-shutdown events
  81     return;
  82   }
  83 
  84   guarantee(phase == init_evac ||
  85             phase == scan_roots ||
  86             phase == update_roots ||
  87             phase == init_traversal_gc_work ||
  88             phase == init_weak_traversal_gc_work ||
  89             phase == final_traversal_gc_work ||
  90             phase == final_traversal_update_roots ||
  91             phase == final_update_refs_roots ||
  92             phase == full_gc_roots ||
  93             phase == degen_gc_update_roots ||
  94             phase == _num_phases,
  95             "only in these phases we can add per-thread phase times");
  96   if (phase != _num_phases) {
  97     // Merge _phase_time to counters below the given phase.
  98     for (uint i = 0; i < GCParPhasesSentinel; i++) {
  99       double t = _worker_times->average(i);
 100       _timing_data[phase + i + 1]._secs.add(t);
 101     }
 102   }
 103 }
 104 
 105 void ShenandoahPhaseTimings::print_on(outputStream* out) const {
 106   out->cr();
 107   out->print_cr("GC STATISTICS:");
 108   out->print_cr("  \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
 109   out->print_cr("        and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect.");
 110   out->print_cr("  \"(N)\" (net) pauses are the times spent in the actual GC code.");
 111   out->print_cr("  \"a\" is average time for each phase, look at levels to see if average makes sense.");
 112   out->print_cr("  \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum).");
 113   out->cr();
 114 
 115   for (uint i = 0; i < _num_phases; i++) {
 116     if (_timing_data[i]._secs.maximum() != 0) {
 117       print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs));
 118     }
 119   }
 120 }
 121 
 122 void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const {
 123   out->print_cr("%-27s = %8.2lf s (a = %8.0lf us) (n = " INT32_FORMAT_W(5) ") (lvls, us = %8.0lf, %8.0lf, %8.0lf, %8.0lf, %8.0lf)",
 124           str,
 125           seq->sum(),
 126           seq->avg() * 1000000.0,
 127           seq->num(),
 128           seq->percentile(0)  * 1000000.0,
 129           seq->percentile(25) * 1000000.0,
 130           seq->percentile(50) * 1000000.0,
 131           seq->percentile(75) * 1000000.0,
 132           seq->maximum() * 1000000.0
 133   );
 134 }
 135 
 136 ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) :
 137         _max_gc_threads(max_gc_threads)
 138 {
 139   assert(max_gc_threads > 0, "Must have some GC threads");
 140 
 141 #define GC_PAR_PHASE_DECLARE_WORKER_DATA(type, title) \
 142   _gc_par_phases[ShenandoahPhaseTimings::type] = new ShenandoahWorkerDataArray<double>(max_gc_threads, title);
 143   // Root scanning phases
 144   SHENANDOAH_GC_PAR_PHASE_DO(GC_PAR_PHASE_DECLARE_WORKER_DATA)
 145 #undef GC_PAR_PHASE_DECLARE_WORKER_DATA
 146 }
 147 
 148 // record the time a phase took in seconds
 149 void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) {
 150   _gc_par_phases[phase]->set(worker_i, secs);
 151 }
 152 
 153 double ShenandoahWorkerTimings::average(uint i) {
 154   return _gc_par_phases[i]->average();
 155 }
 156 void ShenandoahWorkerTimings::reset(uint i) {
 157   _gc_par_phases[i]->reset();
 158 }
 159 
 160 void ShenandoahWorkerTimings::print() {
 161   for (uint i = 0; i < ShenandoahPhaseTimings::GCParPhasesSentinel; i++) {
 162     _gc_par_phases[i]->print_summary_on(tty);
 163   }
 164 }
 165 
 166 
 167 ShenandoahTerminationTimings::ShenandoahTerminationTimings(uint max_gc_threads) {
 168   _gc_termination_phase = new ShenandoahWorkerDataArray<double>(max_gc_threads, "Task Termination (ms):");
 169 }
 170 
 171 void ShenandoahTerminationTimings::record_time_secs(uint worker_id, double secs) {
 172   if (_gc_termination_phase->get(worker_id) == ShenandoahWorkerDataArray<double>::uninitialized()) {
 173     _gc_termination_phase->set(worker_id, secs);
 174   } else {
 175     // worker may re-enter termination phase
 176     _gc_termination_phase->add(worker_id, secs);
 177   }
 178 }
 179 
 180 void ShenandoahTerminationTimings::print() const {
 181   _gc_termination_phase->print_summary_on(tty);
 182 }
 183 
 184 double ShenandoahTerminationTimings::average() const {
 185   return _gc_termination_phase->average();
 186 }
 187 
 188 void ShenandoahTerminationTimings::reset() {
 189   _gc_termination_phase->reset();
 190 }
 191