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