1 /*
2 * Copyright (c) 2017, 2020, Red Hat, Inc. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24
25 #include "precompiled.hpp"
26
27 #include "gc/shared/workerDataArray.inline.hpp"
28 #include "gc/shenandoah/shenandoahCollectorPolicy.hpp"
29 #include "gc/shenandoah/shenandoahPhaseTimings.hpp"
30 #include "gc/shenandoah/shenandoahHeap.hpp"
31 #include "gc/shenandoah/shenandoahHeuristics.hpp"
32 #include "gc/shenandoah/shenandoahUtils.hpp"
33 #include "utilities/ostream.hpp"
34
35 #define GC_PHASE_DECLARE_NAME(type, title) \
36 title,
37
38 const char* ShenandoahPhaseTimings::_phase_names[] = {
39 SHENANDOAH_GC_PHASE_DO(GC_PHASE_DECLARE_NAME)
40 };
41
42 #undef GC_PHASE_DECLARE_NAME
43
44 ShenandoahPhaseTimings::ShenandoahPhaseTimings() : _policy(NULL) {
45 uint max_workers = MAX2(ConcGCThreads, ParallelGCThreads);
46 _worker_times = new ShenandoahWorkerTimings(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 == full_gc_purge_par ||
94 phase == purge_par ||
95 phase == _num_phases,
96 "only in these phases we can add per-thread phase times");
97 if (phase != _num_phases) {
98 // Merge _phase_time to counters below the given phase.
99 for (uint i = 0; i < GCParPhasesSentinel; i++) {
100 double t = _worker_times->average(i);
101 _timing_data[phase + i + 1]._secs.add(t);
102 }
103 }
104 }
105
106 void ShenandoahPhaseTimings::print_on(outputStream* out) const {
107 out->cr();
108 out->print_cr("GC STATISTICS:");
109 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
110 out->print_cr(" and post-safepoint housekeeping. Use -Xlog:safepoint+stats to dissect.");
111 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code.");
112 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense.");
113 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum).");
114 out->cr();
115
116 for (uint i = 0; i < _num_phases; i++) {
117 if (_timing_data[i]._secs.maximum() != 0) {
118 print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs));
119 }
120 }
121 }
122
123 void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const {
124 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)",
125 str,
126 seq->sum(),
127 seq->avg() * 1000000.0,
128 seq->num(),
129 seq->percentile(0) * 1000000.0,
130 seq->percentile(25) * 1000000.0,
131 seq->percentile(50) * 1000000.0,
132 seq->percentile(75) * 1000000.0,
133 seq->maximum() * 1000000.0
134 );
135 }
136
137 ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) :
138 _max_gc_threads(max_gc_threads)
139 {
140 assert(max_gc_threads > 0, "Must have some GC threads");
141
142 #define GC_PAR_PHASE_DECLARE_WORKER_DATA(type, title) \
143 _gc_par_phases[ShenandoahPhaseTimings::type] = new WorkerDataArray<double>(title, max_gc_threads);
144 // Root scanning phases
145 SHENANDOAH_GC_PAR_PHASE_DO(GC_PAR_PHASE_DECLARE_WORKER_DATA)
146 #undef GC_PAR_PHASE_DECLARE_WORKER_DATA
147 }
148
149 // record the time a phase took in seconds
150 void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) {
151 _gc_par_phases[phase]->set(worker_i, secs);
152 }
153
154 double ShenandoahWorkerTimings::average(uint i) const {
155 return _gc_par_phases[i]->average();
156 }
157
158 void ShenandoahWorkerTimings::reset(uint i) {
159 _gc_par_phases[i]->reset();
160 }
161
162 void ShenandoahWorkerTimings::print() const {
163 for (uint i = 0; i < ShenandoahPhaseTimings::GCParPhasesSentinel; i++) {
164 _gc_par_phases[i]->print_summary_on(tty);
165 }
166 }