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, bool should_aggregate) {
146 const double cycle_data = _cycle_data[phase];
147 if (should_aggregate) {
148 _cycle_data[phase] = (cycle_data == uninitialized()) ? time : (cycle_data + time);
149 } else {
150 #ifdef ASSERT
151 assert(cycle_data == uninitialized(), "Should not be set yet: %s, current value: %lf", phase_name(phase), cycle_data);
152 #endif
153 _cycle_data[phase] = time;
154 }
155 }
156
157 void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time, bool should_aggregate) {
158 if (!_policy->is_at_shutdown()) {
159 set_cycle_data(phase, time, should_aggregate);
160 }
161 }
162
163 void ShenandoahPhaseTimings::record_workers_start(Phase phase) {
164 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
165
166 // Special case: these phases can enter multiple times, need to reset
167 // their worker data every time.
168 if (phase == heap_iteration_roots) {
169 for (uint i = 1; i < _num_par_phases; i++) {
170 worker_data(phase, ParPhase(i))->reset();
171 }
172 }
173
174 #ifdef ASSERT
175 for (uint i = 1; i < _num_par_phases; i++) {
176 ShenandoahWorkerData* wd = worker_data(phase, ParPhase(i));
177 for (uint c = 0; c < _max_workers; c++) {
178 assert(wd->get(c) == ShenandoahWorkerData::uninitialized(),
179 "Should not be set: %s", phase_name(worker_par_phase(phase, ParPhase(i))));
180 }
181 }
182 #endif
183 }
184
185 void ShenandoahPhaseTimings::record_workers_end(Phase phase) {
186 assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
187 }
188
189 void ShenandoahPhaseTimings::flush_par_workers_to_cycle() {
190 for (uint pi = 0; pi < _num_phases; pi++) {
191 Phase phase = Phase(pi);
192 if (is_worker_phase(phase)) {
193 double sum = uninitialized();
194 for (uint i = 1; i < _num_par_phases; i++) {
195 ShenandoahWorkerData* wd = worker_data(phase, ParPhase(i));
196 double worker_sum = uninitialized();
197 for (uint c = 0; c < _max_workers; c++) {
198 double worker_time = wd->get(c);
199 if (worker_time != ShenandoahWorkerData::uninitialized()) {
200 if (worker_sum == uninitialized()) {
201 worker_sum = worker_time;
202 } else {
203 worker_sum += worker_time;
204 }
205 }
206 }
207 if (worker_sum != uninitialized()) {
208 // add to each line in phase
209 set_cycle_data(Phase(phase + i + 1), worker_sum);
210 if (sum == uninitialized()) {
211 sum = worker_sum;
212 } else {
213 sum += worker_sum;
214 }
215 }
216 }
217 if (sum != uninitialized()) {
218 // add to total for phase
219 set_cycle_data(Phase(phase + 1), sum);
220 }
221 }
222 }
223 }
224
225 void ShenandoahPhaseTimings::flush_cycle_to_global() {
226 for (uint i = 0; i < _num_phases; i++) {
227 if (_cycle_data[i] != uninitialized()) {
228 _global_data[i].add(_cycle_data[i]);
229 _cycle_data[i] = uninitialized();
230 }
231 if (_worker_data[i] != nullptr) {
232 _worker_data[i]->reset();
233 }
234 }
235 OrderAccess::fence();
236 }
237
238 void ShenandoahPhaseTimings::print_cycle_on(outputStream* out) const {
239 out->cr();
240 out->print_cr("All times are wall-clock times, except per-root-class counters, that are sum over");
241 out->print_cr("all workers. Dividing the <total> over the root stage time estimates parallelism.");
242 out->cr();
243 for (uint i = 0; i < _num_phases; i++) {
244 double v = _cycle_data[i] * 1000000.0;
245 if (v > 0) {
246 out->print(SHENANDOAH_PHASE_NAME_FORMAT " " SHENANDOAH_US_TIME_FORMAT " us", _phase_names[i], v);
247
248 if (is_worker_phase(Phase(i))) {
249 double total = _cycle_data[i + 1] * 1000000.0;
250 if (total > 0) {
251 out->print(", parallelism: " SHENANDOAH_PARALLELISM_FORMAT "x", total / v);
252 }
253 }
254
255 if (_worker_data[i] != nullptr) {
256 out->print(", workers (us): ");
257 for (uint c = 0; c < _max_workers; c++) {
258 double tv = _worker_data[i]->get(c);
259 if (tv != ShenandoahWorkerData::uninitialized()) {
260 out->print(SHENANDOAH_US_WORKER_TIME_FORMAT ", ", tv * 1000000.0);
261 } else {
262 out->print(SHENANDOAH_US_WORKER_NOTIME_FORMAT ", ", "---");
263 }
264 }
265 }
266 out->cr();
267 }
268 }
269 }
270
271 void ShenandoahPhaseTimings::print_global_on(outputStream* out) const {
272 out->cr();
273 out->print_cr("GC STATISTICS:");
274 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
275 out->print_cr(" and post-safepoint housekeeping. Use -Xlog:safepoint+stats to dissect.");
276 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code.");
277 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense.");
278 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum).");
279 out->cr();
280 out->print_cr(" All times are wall-clock times, except per-root-class counters, that are sum over");
281 out->print_cr(" all workers. Dividing the <total> over the root stage time estimates parallelism.");
282 out->cr();
283
284 out->print_cr(" Pacing delays are measured from entering the pacing code till exiting it. Therefore,");
285 out->print_cr(" observed pacing delays may be higher than the threshold when paced thread spent more");
286 out->print_cr(" time in the pacing code. It usually happens when thread is de-scheduled while paced,");
287 out->print_cr(" OS takes longer to unblock the thread, or JVM experiences an STW pause.");
288 out->cr();
289 out->print_cr(" Higher delay would prevent application outpacing the GC, but it will hide the GC latencies");
290 out->print_cr(" from the STW pause times. Pacing affects the individual threads, and so it would also be");
291 out->print_cr(" invisible to the usual profiling tools, but would add up to end-to-end application latency.");
292 out->print_cr(" Raise max pacing delay with care.");
293 out->cr();
294
295 for (uint i = 0; i < _num_phases; i++) {
296 if (_global_data[i].maximum() != 0) {
297 out->print_cr(SHENANDOAH_PHASE_NAME_FORMAT " = " SHENANDOAH_S_TIME_FORMAT " s "
298 "(a = " SHENANDOAH_US_TIME_FORMAT " us) "
299 "(n = " INT32_FORMAT_W(5) ") (lvls, us = "
300 SHENANDOAH_US_TIME_FORMAT ", "
301 SHENANDOAH_US_TIME_FORMAT ", "
302 SHENANDOAH_US_TIME_FORMAT ", "
303 SHENANDOAH_US_TIME_FORMAT ", "
304 SHENANDOAH_US_TIME_FORMAT ")",
305 _phase_names[i],
306 _global_data[i].sum(),
307 _global_data[i].avg() * 1000000.0,
308 _global_data[i].num(),
309 _global_data[i].percentile(0) * 1000000.0,
310 _global_data[i].percentile(25) * 1000000.0,
311 _global_data[i].percentile(50) * 1000000.0,
312 _global_data[i].percentile(75) * 1000000.0,
313 _global_data[i].maximum() * 1000000.0
314 );
315 }
316 }
317 }
318
319 ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahPhaseTimings::Phase phase,
320 ShenandoahPhaseTimings::ParPhase par_phase, uint worker_id, bool cumulative) :
321 _timings(ShenandoahHeap::heap()->phase_timings()),
322 _phase(phase), _par_phase(par_phase), _worker_id(worker_id) {
323
324 assert(_timings->worker_data(_phase, _par_phase)->get(_worker_id) == ShenandoahWorkerData::uninitialized() || cumulative,
325 "Should not be set yet: %s", ShenandoahPhaseTimings::phase_name(_timings->worker_par_phase(_phase, _par_phase)));
326 _start_time = os::elapsedTime();
327 }
328
329 ShenandoahWorkerTimingsTracker::~ShenandoahWorkerTimingsTracker() {
330 _timings->worker_data(_phase, _par_phase)->set_or_add(_worker_id, os::elapsedTime() - _start_time);
331
332 if (ShenandoahPhaseTimings::is_root_work_phase(_phase)) {
333 ShenandoahPhaseTimings::Phase root_phase = _phase;
334 ShenandoahPhaseTimings::Phase cur_phase = _timings->worker_par_phase(root_phase, _par_phase);
335 _event.commit(GCId::current(), _worker_id, ShenandoahPhaseTimings::phase_name(cur_phase));
336 }
337 }