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.inline.hpp"
31 #include "gc/shenandoah/shenandoahUtils.hpp"
32 #include "gc/shenandoah/heuristics/shenandoahHeuristics.hpp"
33 #include "runtime/orderAccess.hpp"
34 #include "utilities/ostream.hpp"
35
36 #define SHENANDOAH_PHASE_NAME_FORMAT "%-30s"
37 #define SHENANDOAH_S_TIME_FORMAT "%8.3lf"
38 #define SHENANDOAH_US_TIME_FORMAT "%8.0lf"
39 #define SHENANDOAH_US_WORKER_TIME_FORMAT "%3.0lf"
40 #define SHENANDOAH_US_WORKER_NOTIME_FORMAT "%3s"
41 #define SHENANDOAH_PARALLELISM_FORMAT "%4.2lf"
42
43 #define SHENANDOAH_PHASE_DECLARE_NAME(type, title) \
44 title,
45
46 const char* ShenandoahPhaseTimings::_phase_names[] = {
47 SHENANDOAH_PHASE_DO(SHENANDOAH_PHASE_DECLARE_NAME)
48 };
49
50 #undef SHENANDOAH_PHASE_DECLARE_NAME
51
52 ShenandoahPhaseTimings::ShenandoahPhaseTimings(uint max_workers) :
53 _max_workers(max_workers) {
54 assert(_max_workers > 0, "Must have some GC threads");
55
56 // Initialize everything to sane defaults
57 for (uint i = 0; i < _num_phases; i++) {
58 #define SHENANDOAH_WORKER_DATA_NULL(type, title) \
59 _worker_data[i] = NULL;
60 SHENANDOAH_PAR_PHASE_DO(,, SHENANDOAH_WORKER_DATA_NULL)
61 #undef SHENANDOAH_WORKER_DATA_NULL
62 _cycle_data[i] = uninitialized();
63 }
64
65 // Then punch in the worker-related data.
66 // Every worker phase get a bunch of internal objects, except
67 // the very first slot, which is "<total>" and is not populated.
68 for (uint i = 0; i < _num_phases; i++) {
69 if (is_worker_phase(Phase(i))) {
70 int c = 0;
71 #define SHENANDOAH_WORKER_DATA_INIT(type, title) \
72 if (c++ != 0) _worker_data[i + c] = new ShenandoahWorkerData(title, _max_workers);
73 SHENANDOAH_PAR_PHASE_DO(,, SHENANDOAH_WORKER_DATA_INIT)
74 #undef SHENANDOAH_WORKER_DATA_INIT
75 }
76 }
77
78 _policy = ShenandoahHeap::heap()->shenandoah_policy();
79 assert(_policy != NULL, "Can not be NULL");
80 }
81
82 ShenandoahPhaseTimings::Phase ShenandoahPhaseTimings::worker_par_phase(Phase phase, ParPhase par_phase) {
83 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
84 Phase p = Phase(phase + 1 + par_phase);
85 assert(p >= 0 && p < _num_phases, "Out of bound for: %s", phase_name(phase));
86 return p;
87 }
88
89 ShenandoahWorkerData* ShenandoahPhaseTimings::worker_data(Phase phase, ParPhase par_phase) {
90 Phase p = worker_par_phase(phase, par_phase);
91 ShenandoahWorkerData* wd = _worker_data[p];
92 assert(wd != NULL, "Counter initialized: %s", phase_name(p));
93 return wd;
94 }
95
96 bool ShenandoahPhaseTimings::is_worker_phase(Phase phase) {
97 assert(phase >= 0 && phase < _num_phases, "Out of bounds");
98 switch (phase) {
99 case init_evac:
100 case scan_roots:
101 case update_roots:
102 case final_update_refs_roots:
103 case full_gc_scan_roots:
104 case full_gc_update_roots:
105 case full_gc_adjust_roots:
106 case degen_gc_scan_conc_roots:
107 case degen_gc_update_roots:
108 case full_gc_scan_conc_roots:
109 case full_gc_purge_class_unload:
110 case full_gc_purge_weak_par:
111 case purge_class_unload:
112 case purge_weak_par:
113 case heap_iteration_roots:
114 case conc_mark_roots:
115 case conc_weak_roots_work:
116 case conc_strong_roots:
117 return true;
118 default:
119 return false;
120 }
121 }
122
123 bool ShenandoahPhaseTimings::is_root_work_phase(Phase phase) {
124 switch (phase) {
125 case scan_roots:
126 case update_roots:
127 case init_evac:
128 case final_update_refs_roots:
129 case degen_gc_update_roots:
130 case full_gc_scan_roots:
131 case full_gc_update_roots:
132 case full_gc_adjust_roots:
133 return true;
134 default:
135 return false;
136 }
137 }
138
139 void ShenandoahPhaseTimings::set_cycle_data(Phase phase, double time) {
140 #ifdef ASSERT
141 double d = _cycle_data[phase];
142 assert(d == uninitialized(), "Should not be set yet: %s, current value: %lf", phase_name(phase), d);
143 #endif
144 _cycle_data[phase] = time;
145 }
146
147 void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time) {
148 if (!_policy->is_at_shutdown()) {
149 set_cycle_data(phase, time);
150 }
151 }
152
153 void ShenandoahPhaseTimings::record_workers_start(Phase phase) {
154 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
155
156 // Special case: these phases can enter multiple times, need to reset
157 // their worker data every time.
158 if (phase == heap_iteration_roots) {
159 for (uint i = 1; i < _num_par_phases; i++) {
160 worker_data(phase, ParPhase(i))->reset();
161 }
162 }
163
164 #ifdef ASSERT
165 for (uint i = 1; i < _num_par_phases; i++) {
166 ShenandoahWorkerData* wd = worker_data(phase, ParPhase(i));
167 for (uint c = 0; c < _max_workers; c++) {
168 assert(wd->get(c) == ShenandoahWorkerData::uninitialized(),
169 "Should not be set: %s", phase_name(worker_par_phase(phase, ParPhase(i))));
170 }
171 }
172 #endif
173 }
174
175 void ShenandoahPhaseTimings::record_workers_end(Phase phase) {
176 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
177 }
178
179 void ShenandoahPhaseTimings::flush_par_workers_to_cycle() {
180 for (uint pi = 0; pi < _num_phases; pi++) {
181 Phase phase = Phase(pi);
182 if (is_worker_phase(phase)) {
183 double s = uninitialized();
184 for (uint i = 1; i < _num_par_phases; i++) {
185 ShenandoahWorkerData* wd = worker_data(phase, ParPhase(i));
186 double ws = uninitialized();
187 for (uint c = 0; c < _max_workers; c++) {
188 double v = wd->get(c);
189 if (v != ShenandoahWorkerData::uninitialized()) {
190 if (ws == uninitialized()) {
191 ws = v;
192 } else {
193 ws += v;
194 }
195 }
196 }
197 if (ws != uninitialized()) {
198 // add to each line in phase
199 set_cycle_data(Phase(phase + i + 1), ws);
200 if (s == uninitialized()) {
201 s = ws;
202 } else {
203 s += ws;
204 }
205 }
206 }
207 if (s != uninitialized()) {
208 // add to total for phase
209 set_cycle_data(Phase(phase + 1), s);
210 }
211 }
212 }
213 }
214
215 void ShenandoahPhaseTimings::flush_cycle_to_global() {
216 for (uint i = 0; i < _num_phases; i++) {
217 if (_cycle_data[i] != uninitialized()) {
218 _global_data[i].add(_cycle_data[i]);
219 _cycle_data[i] = uninitialized();
220 }
221 if (_worker_data[i] != NULL) {
222 _worker_data[i]->reset();
223 }
224 }
225 OrderAccess::fence();
226 }
227
228 void ShenandoahPhaseTimings::print_cycle_on(outputStream* out) const {
229 out->cr();
230 out->print_cr("All times are wall-clock times, except per-root-class counters, that are sum over");
231 out->print_cr("all workers. Dividing the <total> over the root stage time estimates parallelism.");
232 out->cr();
233 for (uint i = 0; i < _num_phases; i++) {
234 double v = _cycle_data[i] * 1000000.0;
235 if (v > 0) {
236 out->print(SHENANDOAH_PHASE_NAME_FORMAT " " SHENANDOAH_US_TIME_FORMAT " us", _phase_names[i], v);
237
238 if (is_worker_phase(Phase(i))) {
239 double total = _cycle_data[i + 1] * 1000000.0;
240 if (total > 0) {
241 out->print(", parallelism: " SHENANDOAH_PARALLELISM_FORMAT "x", total / v);
242 }
243 }
244
245 if (_worker_data[i] != NULL) {
246 out->print(", workers (us): ");
247 for (uint c = 0; c < _max_workers; c++) {
248 double tv = _worker_data[i]->get(c);
249 if (tv != ShenandoahWorkerData::uninitialized()) {
250 out->print(SHENANDOAH_US_WORKER_TIME_FORMAT ", ", tv * 1000000.0);
251 } else {
252 out->print(SHENANDOAH_US_WORKER_NOTIME_FORMAT ", ", "---");
253 }
254 }
255 }
256 out->cr();
257 }
258 }
259 }
260
261 void ShenandoahPhaseTimings::print_global_on(outputStream* out) const {
262 out->cr();
263 out->print_cr("GC STATISTICS:");
264 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
265 out->print_cr(" and post-safepoint housekeeping. Use -Xlog:safepoint+stats to dissect.");
266 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code.");
267 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense.");
268 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum).");
269 out->cr();
270 out->print_cr(" All times are wall-clock times, except per-root-class counters, that are sum over");
271 out->print_cr(" all workers. Dividing the <total> over the root stage time estimates parallelism.");
272 out->cr();
273
274 for (uint i = 0; i < _num_phases; i++) {
275 if (_global_data[i].maximum() != 0) {
276 out->print_cr(SHENANDOAH_PHASE_NAME_FORMAT " = " SHENANDOAH_S_TIME_FORMAT " s "
277 "(a = " SHENANDOAH_US_TIME_FORMAT " us) "
278 "(n = " INT32_FORMAT_W(5) ") (lvls, us = "
279 SHENANDOAH_US_TIME_FORMAT ", "
280 SHENANDOAH_US_TIME_FORMAT ", "
281 SHENANDOAH_US_TIME_FORMAT ", "
282 SHENANDOAH_US_TIME_FORMAT ", "
283 SHENANDOAH_US_TIME_FORMAT ")",
284 _phase_names[i],
285 _global_data[i].sum(),
286 _global_data[i].avg() * 1000000.0,
287 _global_data[i].num(),
288 _global_data[i].percentile(0) * 1000000.0,
289 _global_data[i].percentile(25) * 1000000.0,
290 _global_data[i].percentile(50) * 1000000.0,
291 _global_data[i].percentile(75) * 1000000.0,
292 _global_data[i].maximum() * 1000000.0
293 );
294 }
295 }
296 }
297
298 ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahPhaseTimings::Phase phase,
299 ShenandoahPhaseTimings::ParPhase par_phase, uint worker_id) :
300 _timings(ShenandoahHeap::heap()->phase_timings()),
301 _phase(phase), _par_phase(par_phase), _worker_id(worker_id) {
302
303 assert(_timings->worker_data(_phase, _par_phase)->get(_worker_id) == ShenandoahWorkerData::uninitialized(),
304 "Should not be set yet: %s", ShenandoahPhaseTimings::phase_name(_timings->worker_par_phase(_phase, _par_phase)));
305 _start_time = os::elapsedTime();
306 }
307
308 ShenandoahWorkerTimingsTracker::~ShenandoahWorkerTimingsTracker() {
309 _timings->worker_data(_phase, _par_phase)->set(_worker_id, os::elapsedTime() - _start_time);
310
311 if (ShenandoahPhaseTimings::is_root_work_phase(_phase)) {
312 ShenandoahPhaseTimings::Phase root_phase = _phase;
313 ShenandoahPhaseTimings::Phase cur_phase = _timings->worker_par_phase(root_phase, _par_phase);
314 _event.commit(GCId::current(), _worker_id, ShenandoahPhaseTimings::phase_name(cur_phase));
315 }
316 }
317