--- /dev/null 2018-11-30 10:10:44.238550338 +0100 +++ new/src/hotspot/share/gc/shenandoah/shenandoahPhaseTimings.cpp 2018-11-30 21:09:17.133739637 +0100 @@ -0,0 +1,191 @@ +/* + * Copyright (c) 2017, 2018, Red Hat, Inc. All rights reserved. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + * + */ + +#include "precompiled.hpp" + +#include "gc/shared/workerDataArray.inline.hpp" +#include "gc/shenandoah/shenandoahCollectorPolicy.hpp" +#include "gc/shenandoah/shenandoahPhaseTimings.hpp" +#include "gc/shenandoah/shenandoahHeap.hpp" +#include "gc/shenandoah/shenandoahHeuristics.hpp" +#include "gc/shenandoah/shenandoahUtils.hpp" +#include "utilities/ostream.hpp" + +#define GC_PHASE_DECLARE_NAME(type, title) \ + title, + +const char* ShenandoahPhaseTimings::_phase_names[] = { + SHENANDOAH_GC_PHASE_DO(GC_PHASE_DECLARE_NAME) +}; + +#undef GC_PHASE_DECLARE_NAME + +ShenandoahPhaseTimings::ShenandoahPhaseTimings() : _policy(NULL) { + uint max_workers = MAX2(ConcGCThreads, ParallelGCThreads); + _worker_times = new ShenandoahWorkerTimings(max_workers); + _termination_times = new ShenandoahTerminationTimings(max_workers); + _policy = ShenandoahHeap::heap()->shenandoah_policy(); + assert(_policy != NULL, "Can not be NULL"); +} + +void ShenandoahPhaseTimings::record_phase_start(Phase phase) { + _timing_data[phase]._start = os::elapsedTime(); +} + +void ShenandoahPhaseTimings::record_phase_end(Phase phase) { + assert(_policy != NULL, "Not yet initialized"); + double end = os::elapsedTime(); + double elapsed = end - _timing_data[phase]._start; + if (!_policy->is_at_shutdown()) { + _timing_data[phase]._secs.add(elapsed); + } + ShenandoahHeap::heap()->heuristics()->record_phase_time(phase, elapsed); +} + +void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time) { + assert(_policy != NULL, "Not yet initialized"); + if (!_policy->is_at_shutdown()) { + _timing_data[phase]._secs.add(time); + } +} + +void ShenandoahPhaseTimings::record_workers_start(Phase phase) { + for (uint i = 0; i < GCParPhasesSentinel; i++) { + _worker_times->reset(i); + } +} + +void ShenandoahPhaseTimings::record_workers_end(Phase phase) { + if (_policy->is_at_shutdown()) { + // Do not record the past-shutdown events + return; + } + + guarantee(phase == init_evac || + phase == scan_roots || + phase == update_roots || + phase == init_traversal_gc_work || + phase == final_traversal_gc_work || + phase == final_traversal_update_roots || + phase == final_update_refs_roots || + phase == full_gc_roots || + phase == degen_gc_update_roots || + phase == _num_phases, + "only in these phases we can add per-thread phase times"); + if (phase != _num_phases) { + // Merge _phase_time to counters below the given phase. + for (uint i = 0; i < GCParPhasesSentinel; i++) { + double t = _worker_times->average(i); + _timing_data[phase + i + 1]._secs.add(t); + } + } +} + +void ShenandoahPhaseTimings::print_on(outputStream* out) const { + out->cr(); + out->print_cr("GC STATISTICS:"); + out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-"); + out->print_cr(" and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect."); + out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code."); + out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense."); + out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum)."); + out->cr(); + + for (uint i = 0; i < _num_phases; i++) { + if (_timing_data[i]._secs.maximum() != 0) { + print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs)); + } + } +} + +void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const { + 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)", + str, + seq->sum(), + seq->avg() * 1000000.0, + seq->num(), + seq->percentile(0) * 1000000.0, + seq->percentile(25) * 1000000.0, + seq->percentile(50) * 1000000.0, + seq->percentile(75) * 1000000.0, + seq->maximum() * 1000000.0 + ); +} + +ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) : + _max_gc_threads(max_gc_threads) +{ + assert(max_gc_threads > 0, "Must have some GC threads"); + +#define GC_PAR_PHASE_DECLARE_WORKER_DATA(type, title) \ + _gc_par_phases[ShenandoahPhaseTimings::type] = new WorkerDataArray(max_gc_threads, title); + // Root scanning phases + SHENANDOAH_GC_PAR_PHASE_DO(GC_PAR_PHASE_DECLARE_WORKER_DATA) +#undef GC_PAR_PHASE_DECLARE_WORKER_DATA +} + +// record the time a phase took in seconds +void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) { + _gc_par_phases[phase]->set(worker_i, secs); +} + +double ShenandoahWorkerTimings::average(uint i) const { + return _gc_par_phases[i]->average(); +} + +void ShenandoahWorkerTimings::reset(uint i) { + _gc_par_phases[i]->reset(); +} + +void ShenandoahWorkerTimings::print() const { + for (uint i = 0; i < ShenandoahPhaseTimings::GCParPhasesSentinel; i++) { + _gc_par_phases[i]->print_summary_on(tty); + } +} + + +ShenandoahTerminationTimings::ShenandoahTerminationTimings(uint max_gc_threads) { + _gc_termination_phase = new WorkerDataArray(max_gc_threads, "Task Termination (ms):"); +} + +void ShenandoahTerminationTimings::record_time_secs(uint worker_id, double secs) { + if (_gc_termination_phase->get(worker_id) == WorkerDataArray::uninitialized()) { + _gc_termination_phase->set(worker_id, secs); + } else { + // worker may re-enter termination phase + _gc_termination_phase->add(worker_id, secs); + } +} + +void ShenandoahTerminationTimings::print() const { + _gc_termination_phase->print_summary_on(tty); +} + +double ShenandoahTerminationTimings::average() const { + return _gc_termination_phase->average(); +} + +void ShenandoahTerminationTimings::reset() { + _gc_termination_phase->reset(); +} +