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/shared/workerDataArray.inline.hpp" 27 #include "gc/shenandoah/shenandoahCollectorPolicy.hpp" 28 #include "gc/shenandoah/shenandoahPhaseTimings.hpp" 29 #include "gc/shenandoah/shenandoahHeap.hpp" 30 #include "gc/shenandoah/shenandoahHeuristics.hpp" 31 #include "gc/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 = 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 == final_traversal_gc_work || 89 phase == final_traversal_update_roots || 90 phase == final_update_refs_roots || 91 phase == full_gc_roots || 92 phase == degen_gc_update_roots || 93 phase == _num_phases, 94 "only in these phases we can add per-thread phase times"); 95 if (phase != _num_phases) { 96 // Merge _phase_time to counters below the given phase. 97 for (uint i = 0; i < GCParPhasesSentinel; i++) { 98 double t = _worker_times->average(i); 99 _timing_data[phase + i + 1]._secs.add(t); 100 } 101 } 102 } 103 104 void ShenandoahPhaseTimings::print_on(outputStream* out) const { 105 out->cr(); 106 out->print_cr("GC STATISTICS:"); 107 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-"); 108 out->print_cr(" and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect."); 109 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code."); 110 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense."); 111 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum)."); 112 out->cr(); 113 114 for (uint i = 0; i < _num_phases; i++) { 115 if (_timing_data[i]._secs.maximum() != 0) { 116 print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs)); 117 } 118 } 119 } 120 121 void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const { 122 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)", 123 str, 124 seq->sum(), 125 seq->avg() * 1000000.0, 126 seq->num(), 127 seq->percentile(0) * 1000000.0, 128 seq->percentile(25) * 1000000.0, 129 seq->percentile(50) * 1000000.0, 130 seq->percentile(75) * 1000000.0, 131 seq->maximum() * 1000000.0 132 ); 133 } 134 135 ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) : 136 _max_gc_threads(max_gc_threads) 137 { 138 assert(max_gc_threads > 0, "Must have some GC threads"); 139 140 #define GC_PAR_PHASE_DECLARE_WORKER_DATA(type, title) \ 141 _gc_par_phases[ShenandoahPhaseTimings::type] = new WorkerDataArray<double>(max_gc_threads, title); 142 // Root scanning phases 143 SHENANDOAH_GC_PAR_PHASE_DO(GC_PAR_PHASE_DECLARE_WORKER_DATA) 144 #undef GC_PAR_PHASE_DECLARE_WORKER_DATA 145 } 146 147 // record the time a phase took in seconds 148 void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) { 149 _gc_par_phases[phase]->set(worker_i, secs); 150 } 151 152 double ShenandoahWorkerTimings::average(uint i) const { 153 return _gc_par_phases[i]->average(); 154 } 155 156 void ShenandoahWorkerTimings::reset(uint i) { 157 _gc_par_phases[i]->reset(); 158 } 159 160 void ShenandoahWorkerTimings::print() const { 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 WorkerDataArray<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) == WorkerDataArray<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