1 /* 2 * Copyright (c) 2017, 2021, Red Hat, Inc. All rights reserved. 3 * Copyright Amazon.com Inc. or its affiliates. All Rights Reserved. 4 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 5 * 6 * This code is free software; you can redistribute it and/or modify it 7 * under the terms of the GNU General Public License version 2 only, as 8 * published by the Free Software Foundation. 9 * 10 * This code is distributed in the hope that it will be useful, but WITHOUT 11 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 12 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 13 * version 2 for more details (a copy is included in the LICENSE file that 14 * accompanied this code). 15 * 16 * You should have received a copy of the GNU General Public License version 17 * 2 along with this work; if not, write to the Free Software Foundation, 18 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 19 * 20 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 21 * or visit www.oracle.com if you need additional information or have any 22 * questions. 23 * 24 */ 25 26 #include "precompiled.hpp" 27 28 #include "gc/shared/workerDataArray.inline.hpp" 29 #include "gc/shenandoah/shenandoahCollectorPolicy.hpp" 30 #include "gc/shenandoah/shenandoahPhaseTimings.hpp" 31 #include "gc/shenandoah/shenandoahHeap.inline.hpp" 32 #include "gc/shenandoah/shenandoahUtils.hpp" 33 #include "gc/shenandoah/heuristics/shenandoahHeuristics.hpp" 34 #include "runtime/orderAccess.hpp" 35 #include "utilities/ostream.hpp" 36 37 #define SHENANDOAH_PHASE_NAME_FORMAT "%-30s" 38 #define SHENANDOAH_S_TIME_FORMAT "%8.3lf" 39 #define SHENANDOAH_US_TIME_FORMAT "%8.0lf" 40 #define SHENANDOAH_US_WORKER_TIME_FORMAT "%3.0lf" 41 #define SHENANDOAH_US_WORKER_NOTIME_FORMAT "%3s" 42 #define SHENANDOAH_PARALLELISM_FORMAT "%4.2lf" 43 44 #define SHENANDOAH_PHASE_DECLARE_NAME(type, title) \ 45 title, 46 47 const char* ShenandoahPhaseTimings::_phase_names[] = { 48 SHENANDOAH_PHASE_DO(SHENANDOAH_PHASE_DECLARE_NAME) 49 }; 50 51 #undef SHENANDOAH_PHASE_DECLARE_NAME 52 53 ShenandoahPhaseTimings::ShenandoahPhaseTimings(uint max_workers) : 54 _max_workers(max_workers) { 55 assert(_max_workers > 0, "Must have some GC threads"); 56 57 // Initialize everything to sane defaults 58 for (uint i = 0; i < _num_phases; i++) { 59 #define SHENANDOAH_WORKER_DATA_NULL(type, title) \ 60 _worker_data[i] = nullptr; 61 SHENANDOAH_PAR_PHASE_DO(,, SHENANDOAH_WORKER_DATA_NULL) 62 #undef SHENANDOAH_WORKER_DATA_NULL 63 _cycle_data[i] = uninitialized(); 64 } 65 66 // Then punch in the worker-related data. 67 // Every worker phase get a bunch of internal objects, except 68 // the very first slot, which is "<total>" and is not populated. 69 for (uint i = 0; i < _num_phases; i++) { 70 if (is_worker_phase(Phase(i))) { 71 int c = 0; 72 #define SHENANDOAH_WORKER_DATA_INIT(type, title) \ 73 if (c++ != 0) _worker_data[i + c] = new ShenandoahWorkerData(nullptr, title, _max_workers); 74 SHENANDOAH_PAR_PHASE_DO(,, SHENANDOAH_WORKER_DATA_INIT) 75 #undef SHENANDOAH_WORKER_DATA_INIT 76 } 77 } 78 79 _policy = ShenandoahHeap::heap()->shenandoah_policy(); 80 assert(_policy != nullptr, "Can not be null"); 81 } 82 83 ShenandoahPhaseTimings::Phase ShenandoahPhaseTimings::worker_par_phase(Phase phase, ParPhase par_phase) { 84 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase)); 85 Phase p = Phase(phase + 1 + par_phase); 86 assert(p >= 0 && p < _num_phases, "Out of bound for: %s", phase_name(phase)); 87 return p; 88 } 89 90 ShenandoahWorkerData* ShenandoahPhaseTimings::worker_data(Phase phase, ParPhase par_phase) { 91 Phase p = worker_par_phase(phase, par_phase); 92 ShenandoahWorkerData* wd = _worker_data[p]; 93 assert(wd != nullptr, "Counter initialized: %s", phase_name(p)); 94 return wd; 95 } 96 97 bool ShenandoahPhaseTimings::is_worker_phase(Phase phase) { 98 assert(phase >= 0 && phase < _num_phases, "Out of bounds"); 99 switch (phase) { 100 case init_evac: 101 case init_scan_rset: 102 case finish_mark: 103 case purge_weak_par: 104 case full_gc_mark: 105 case full_gc_update_roots: 106 case full_gc_adjust_roots: 107 case degen_gc_stw_mark: 108 case degen_gc_mark: 109 case degen_gc_update_roots: 110 case full_gc_weakrefs: 111 case full_gc_purge_class_unload: 112 case full_gc_purge_weak_par: 113 case degen_gc_coalesce_and_fill: 114 case degen_gc_weakrefs: 115 case degen_gc_purge_class_unload: 116 case degen_gc_purge_weak_par: 117 case heap_iteration_roots: 118 case conc_mark: 119 case conc_mark_roots: 120 case conc_thread_roots: 121 case conc_weak_roots_work: 122 case conc_weak_refs: 123 case conc_strong_roots: 124 case conc_coalesce_and_fill: 125 return true; 126 default: 127 return false; 128 } 129 } 130 131 bool ShenandoahPhaseTimings::is_root_work_phase(Phase phase) { 132 switch (phase) { 133 case finish_mark: 134 case init_evac: 135 case degen_gc_update_roots: 136 case full_gc_mark: 137 case full_gc_update_roots: 138 case full_gc_adjust_roots: 139 return true; 140 default: 141 return false; 142 } 143 } 144 145 void ShenandoahPhaseTimings::set_cycle_data(Phase phase, double time) { 146 #ifdef ASSERT 147 double d = _cycle_data[phase]; 148 assert(d == uninitialized(), "Should not be set yet: %s, current value: %lf", phase_name(phase), d); 149 #endif 150 _cycle_data[phase] = time; 151 } 152 153 void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time) { 154 if (!_policy->is_at_shutdown()) { 155 set_cycle_data(phase, time); 156 } 157 } 158 159 void ShenandoahPhaseTimings::record_workers_start(Phase phase) { 160 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase)); 161 162 // Special case: these phases can enter multiple times, need to reset 163 // their worker data every time. 164 if (phase == heap_iteration_roots) { 165 for (uint i = 1; i < _num_par_phases; i++) { 166 worker_data(phase, ParPhase(i))->reset(); 167 } 168 } 169 170 #ifdef ASSERT 171 for (uint i = 1; i < _num_par_phases; i++) { 172 ShenandoahWorkerData* wd = worker_data(phase, ParPhase(i)); 173 for (uint c = 0; c < _max_workers; c++) { 174 assert(wd->get(c) == ShenandoahWorkerData::uninitialized(), 175 "Should not be set: %s", phase_name(worker_par_phase(phase, ParPhase(i)))); 176 } 177 } 178 #endif 179 } 180 181 void ShenandoahPhaseTimings::record_workers_end(Phase phase) { 182 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase)); 183 } 184 185 void ShenandoahPhaseTimings::flush_par_workers_to_cycle() { 186 for (uint pi = 0; pi < _num_phases; pi++) { 187 Phase phase = Phase(pi); 188 if (is_worker_phase(phase)) { 189 double s = uninitialized(); 190 for (uint i = 1; i < _num_par_phases; i++) { 191 ShenandoahWorkerData* wd = worker_data(phase, ParPhase(i)); 192 double ws = uninitialized(); 193 for (uint c = 0; c < _max_workers; c++) { 194 double v = wd->get(c); 195 if (v != ShenandoahWorkerData::uninitialized()) { 196 if (ws == uninitialized()) { 197 ws = v; 198 } else { 199 ws += v; 200 } 201 } 202 } 203 if (ws != uninitialized()) { 204 // add to each line in phase 205 set_cycle_data(Phase(phase + i + 1), ws); 206 if (s == uninitialized()) { 207 s = ws; 208 } else { 209 s += ws; 210 } 211 } 212 } 213 if (s != uninitialized()) { 214 // add to total for phase 215 set_cycle_data(Phase(phase + 1), s); 216 } 217 } 218 } 219 } 220 221 void ShenandoahPhaseTimings::flush_cycle_to_global() { 222 for (uint i = 0; i < _num_phases; i++) { 223 if (_cycle_data[i] != uninitialized()) { 224 _global_data[i].add(_cycle_data[i]); 225 _cycle_data[i] = uninitialized(); 226 } 227 if (_worker_data[i] != nullptr) { 228 _worker_data[i]->reset(); 229 } 230 } 231 OrderAccess::fence(); 232 } 233 234 void ShenandoahPhaseTimings::print_cycle_on(outputStream* out) const { 235 out->cr(); 236 out->print_cr("All times are wall-clock times, except per-root-class counters, that are sum over"); 237 out->print_cr("all workers. Dividing the <total> over the root stage time estimates parallelism."); 238 out->cr(); 239 for (uint i = 0; i < _num_phases; i++) { 240 double v = _cycle_data[i] * 1000000.0; 241 if (v > 0) { 242 out->print(SHENANDOAH_PHASE_NAME_FORMAT " " SHENANDOAH_US_TIME_FORMAT " us", _phase_names[i], v); 243 244 if (is_worker_phase(Phase(i))) { 245 double total = _cycle_data[i + 1] * 1000000.0; 246 if (total > 0) { 247 out->print(", parallelism: " SHENANDOAH_PARALLELISM_FORMAT "x", total / v); 248 } 249 } 250 251 if (_worker_data[i] != nullptr) { 252 out->print(", workers (us): "); 253 for (uint c = 0; c < _max_workers; c++) { 254 double tv = _worker_data[i]->get(c); 255 if (tv != ShenandoahWorkerData::uninitialized()) { 256 out->print(SHENANDOAH_US_WORKER_TIME_FORMAT ", ", tv * 1000000.0); 257 } else { 258 out->print(SHENANDOAH_US_WORKER_NOTIME_FORMAT ", ", "---"); 259 } 260 } 261 } 262 out->cr(); 263 } 264 } 265 } 266 267 void ShenandoahPhaseTimings::print_global_on(outputStream* out) const { 268 out->cr(); 269 out->print_cr("GC STATISTICS:"); 270 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-"); 271 out->print_cr(" and post-safepoint housekeeping. Use -Xlog:safepoint+stats to dissect."); 272 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code."); 273 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense."); 274 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum)."); 275 out->cr(); 276 out->print_cr(" All times are wall-clock times, except per-root-class counters, that are sum over"); 277 out->print_cr(" all workers. Dividing the <total> over the root stage time estimates parallelism."); 278 out->cr(); 279 280 out->print_cr(" Pacing delays are measured from entering the pacing code till exiting it. Therefore,"); 281 out->print_cr(" observed pacing delays may be higher than the threshold when paced thread spent more"); 282 out->print_cr(" time in the pacing code. It usually happens when thread is de-scheduled while paced,"); 283 out->print_cr(" OS takes longer to unblock the thread, or JVM experiences an STW pause."); 284 out->cr(); 285 out->print_cr(" Higher delay would prevent application outpacing the GC, but it will hide the GC latencies"); 286 out->print_cr(" from the STW pause times. Pacing affects the individual threads, and so it would also be"); 287 out->print_cr(" invisible to the usual profiling tools, but would add up to end-to-end application latency."); 288 out->print_cr(" Raise max pacing delay with care."); 289 out->cr(); 290 291 for (uint i = 0; i < _num_phases; i++) { 292 if (_global_data[i].maximum() != 0) { 293 out->print_cr(SHENANDOAH_PHASE_NAME_FORMAT " = " SHENANDOAH_S_TIME_FORMAT " s " 294 "(a = " SHENANDOAH_US_TIME_FORMAT " us) " 295 "(n = " INT32_FORMAT_W(5) ") (lvls, us = " 296 SHENANDOAH_US_TIME_FORMAT ", " 297 SHENANDOAH_US_TIME_FORMAT ", " 298 SHENANDOAH_US_TIME_FORMAT ", " 299 SHENANDOAH_US_TIME_FORMAT ", " 300 SHENANDOAH_US_TIME_FORMAT ")", 301 _phase_names[i], 302 _global_data[i].sum(), 303 _global_data[i].avg() * 1000000.0, 304 _global_data[i].num(), 305 _global_data[i].percentile(0) * 1000000.0, 306 _global_data[i].percentile(25) * 1000000.0, 307 _global_data[i].percentile(50) * 1000000.0, 308 _global_data[i].percentile(75) * 1000000.0, 309 _global_data[i].maximum() * 1000000.0 310 ); 311 } 312 } 313 } 314 315 ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahPhaseTimings::Phase phase, 316 ShenandoahPhaseTimings::ParPhase par_phase, uint worker_id, bool cumulative) : 317 _timings(ShenandoahHeap::heap()->phase_timings()), 318 _phase(phase), _par_phase(par_phase), _worker_id(worker_id) { 319 320 assert(_timings->worker_data(_phase, _par_phase)->get(_worker_id) == ShenandoahWorkerData::uninitialized() || cumulative, 321 "Should not be set yet: %s", ShenandoahPhaseTimings::phase_name(_timings->worker_par_phase(_phase, _par_phase))); 322 _start_time = os::elapsedTime(); 323 } 324 325 ShenandoahWorkerTimingsTracker::~ShenandoahWorkerTimingsTracker() { 326 _timings->worker_data(_phase, _par_phase)->set_or_add(_worker_id, os::elapsedTime() - _start_time); 327 328 if (ShenandoahPhaseTimings::is_root_work_phase(_phase)) { 329 ShenandoahPhaseTimings::Phase root_phase = _phase; 330 ShenandoahPhaseTimings::Phase cur_phase = _timings->worker_par_phase(root_phase, _par_phase); 331 _event.commit(GCId::current(), _worker_id, ShenandoahPhaseTimings::phase_name(cur_phase)); 332 } 333 }