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 _termination_times = new ShenandoahTerminationTimings(max_workers);
48 _policy = ShenandoahHeap::heap()->shenandoah_policy();
49 assert(_policy != NULL, "Can not be NULL");
50 }
51
52 void ShenandoahPhaseTimings::record_phase_start(Phase phase) {
53 _timing_data[phase]._start = os::elapsedTime();
54 }
55
56 void ShenandoahPhaseTimings::record_phase_end(Phase phase) {
57 assert(_policy != NULL, "Not yet initialized");
58 double end = os::elapsedTime();
59 double elapsed = end - _timing_data[phase]._start;
60 if (!_policy->is_at_shutdown()) {
61 _timing_data[phase]._secs.add(elapsed);
62 }
63 ShenandoahHeap::heap()->heuristics()->record_phase_time(phase, elapsed);
64 }
65
66 void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time) {
67 assert(_policy != NULL, "Not yet initialized");
68 if (!_policy->is_at_shutdown()) {
69 _timing_data[phase]._secs.add(time);
70 }
71 }
72
73 void ShenandoahPhaseTimings::record_workers_start(Phase phase) {
74 for (uint i = 0; i < GCParPhasesSentinel; i++) {
75 _worker_times->reset(i);
76 }
77 }
78
79 void ShenandoahPhaseTimings::record_workers_end(Phase phase) {
80 if (_policy->is_at_shutdown()) {
81 // Do not record the past-shutdown events
82 return;
83 }
84
85 guarantee(phase == init_evac ||
86 phase == scan_roots ||
87 phase == update_roots ||
88 phase == init_traversal_gc_work ||
89 phase == final_traversal_gc_work ||
90 phase == final_traversal_update_roots ||
91 phase == final_update_refs_roots ||
92 phase == full_gc_roots ||
93 phase == degen_gc_update_roots ||
94 phase == full_gc_purge_par ||
95 phase == purge_par ||
96 phase == _num_phases,
97 "only in these phases we can add per-thread phase times");
98 if (phase != _num_phases) {
99 // Merge _phase_time to counters below the given phase.
100 for (uint i = 0; i < GCParPhasesSentinel; i++) {
101 double t = _worker_times->average(i);
102 _timing_data[phase + i + 1]._secs.add(t);
103 }
104 }
105 }
106
107 void ShenandoahPhaseTimings::print_on(outputStream* out) const {
108 out->cr();
109 out->print_cr("GC STATISTICS:");
110 out->print_cr(" \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
111 out->print_cr(" and post-safepoint housekeeping. Use -Xlog:safepoint+stats to dissect.");
112 out->print_cr(" \"(N)\" (net) pauses are the times spent in the actual GC code.");
113 out->print_cr(" \"a\" is average time for each phase, look at levels to see if average makes sense.");
114 out->print_cr(" \"lvls\" are quantiles: 0%% (minimum), 25%%, 50%% (median), 75%%, 100%% (maximum).");
115 out->cr();
116
117 for (uint i = 0; i < _num_phases; i++) {
118 if (_timing_data[i]._secs.maximum() != 0) {
119 print_summary_sd(out, _phase_names[i], &(_timing_data[i]._secs));
120 }
121 }
122 }
123
124 void ShenandoahPhaseTimings::print_summary_sd(outputStream* out, const char* str, const HdrSeq* seq) const {
125 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)",
126 str,
127 seq->sum(),
128 seq->avg() * 1000000.0,
129 seq->num(),
130 seq->percentile(0) * 1000000.0,
131 seq->percentile(25) * 1000000.0,
132 seq->percentile(50) * 1000000.0,
133 seq->percentile(75) * 1000000.0,
134 seq->maximum() * 1000000.0
135 );
136 }
137
138 ShenandoahWorkerTimings::ShenandoahWorkerTimings(uint max_gc_threads) :
139 _max_gc_threads(max_gc_threads)
140 {
141 assert(max_gc_threads > 0, "Must have some GC threads");
142
143 #define GC_PAR_PHASE_DECLARE_WORKER_DATA(type, title) \
144 _gc_par_phases[ShenandoahPhaseTimings::type] = new WorkerDataArray<double>(title, max_gc_threads);
145 // Root scanning phases
146 SHENANDOAH_GC_PAR_PHASE_DO(GC_PAR_PHASE_DECLARE_WORKER_DATA)
147 #undef GC_PAR_PHASE_DECLARE_WORKER_DATA
148 }
149
150 // record the time a phase took in seconds
151 void ShenandoahWorkerTimings::record_time_secs(ShenandoahPhaseTimings::GCParPhases phase, uint worker_i, double secs) {
152 _gc_par_phases[phase]->set(worker_i, secs);
153 }
154
155 double ShenandoahWorkerTimings::average(uint i) const {
156 return _gc_par_phases[i]->average();
157 }
158
159 void ShenandoahWorkerTimings::reset(uint i) {
160 _gc_par_phases[i]->reset();
161 }
162
163 void ShenandoahWorkerTimings::print() const {
164 for (uint i = 0; i < ShenandoahPhaseTimings::GCParPhasesSentinel; i++) {
165 _gc_par_phases[i]->print_summary_on(tty);
166 }
167 }
168
169
170 ShenandoahTerminationTimings::ShenandoahTerminationTimings(uint max_gc_threads) {
171 _gc_termination_phase = new WorkerDataArray<double>("Task Termination (ms):", max_gc_threads);
172 }
173
174 void ShenandoahTerminationTimings::record_time_secs(uint worker_id, double secs) {
175 if (_gc_termination_phase->get(worker_id) == WorkerDataArray<double>::uninitialized()) {
176 _gc_termination_phase->set(worker_id, secs);
177 } else {
178 // worker may re-enter termination phase
179 _gc_termination_phase->add(worker_id, secs);
180 }
181 }
182
183 void ShenandoahTerminationTimings::print() const {
184 _gc_termination_phase->print_summary_on(tty);
185 }
186
187 double ShenandoahTerminationTimings::average() const {
188 return _gc_termination_phase->average();
189 }
190
191 void ShenandoahTerminationTimings::reset() {
192 _gc_termination_phase->reset();
193 }
194