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