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