1/*
2 * Copyright (c) 2018, 2019, Oracle and/or its affiliates. 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#include "gc/shared/weakProcessorPhases.hpp"
27#include "gc/shared/weakProcessorPhaseTimes.hpp"
28#include "gc/shared/workerDataArray.inline.hpp"
29#include "logging/log.hpp"
30#include "logging/logStream.hpp"
31#include "utilities/debug.hpp"
32#include "utilities/globalDefinitions.hpp"
33#include "utilities/ticks.hpp"
34
35static uint phase_index(WeakProcessorPhase phase) {
36 return WeakProcessorPhases::index(phase);
37}
38
39static bool is_serial_phase(WeakProcessorPhase phase) {
40 return WeakProcessorPhases::is_serial(phase);
41}
42
43static void assert_oop_storage_phase(WeakProcessorPhase phase) {
44 assert(WeakProcessorPhases::is_oop_storage(phase),
45 "Not an oop_storage phase %u", phase_index(phase));
46}
47
48const double uninitialized_time = -1.0;
49
50#ifdef ASSERT
51static bool is_initialized_time(double t) { return t >= 0.0; }
52static bool is_initialized_items(size_t i) { return i != 0; }
53#endif // ASSERT
54
55static void reset_times(double* times, size_t ntimes) {
56 for (size_t i = 0; i < ntimes; ++i) {
57 times[i] = uninitialized_time;
58 }
59}
60
61static void reset_items(size_t* items, size_t nitems) {
62 for (size_t i = 0; i < nitems; ++i) {
63 items[i] = 0;
64 }
65}
66
67WeakProcessorPhaseTimes::WeakProcessorPhaseTimes(uint max_threads) :
68 _max_threads(max_threads),
69 _active_workers(0),
70 _total_time_sec(uninitialized_time),
71 _worker_data(),
72 _worker_dead_items(),
73 _worker_total_items()
74{
75 assert(_max_threads > 0, "max_threads must not be zero");
76
77 reset_times(_phase_times_sec, ARRAY_SIZE(_phase_times_sec));
78 reset_items(_phase_dead_items, ARRAY_SIZE(_phase_dead_items));
79 reset_items(_phase_total_items, ARRAY_SIZE(_phase_total_items));
80
81 if (_max_threads > 1) {
82 WorkerDataArray<double>** wpt = _worker_data;
83 FOR_EACH_WEAK_PROCESSOR_OOP_STORAGE_PHASE(phase) {
84 const char* description = WeakProcessorPhases::description(phase);
85 *wpt = new WorkerDataArray<double>(_max_threads, description);
86 (*wpt)->link_thread_work_items(new WorkerDataArray<size_t>(_max_threads, "Dead"), DeadItems);
87 (*wpt)->link_thread_work_items(new WorkerDataArray<size_t>(_max_threads, "Total"), TotalItems);
88 wpt++;
89 }
90 }
91}
92
93WeakProcessorPhaseTimes::~WeakProcessorPhaseTimes() {
94 for (size_t i = 0; i < ARRAY_SIZE(_worker_data); ++i) {
95 delete _worker_data[i];
96 delete _worker_dead_items[i];
97 delete _worker_total_items[i];
98 }
99}
100
101uint WeakProcessorPhaseTimes::max_threads() const { return _max_threads; }
102
103uint WeakProcessorPhaseTimes::active_workers() const {
104 assert(_active_workers != 0, "active workers not set");
105 return _active_workers;
106}
107
108void WeakProcessorPhaseTimes::set_active_workers(uint n) {
109 assert(_active_workers == 0, "active workers already set");
110 assert(n > 0, "active workers must be non-zero");
111 assert(n <= _max_threads, "active workers must not exceed max threads");
112 _active_workers = n;
113}
114
115void WeakProcessorPhaseTimes::reset() {
116 _active_workers = 0;
117 _total_time_sec = uninitialized_time;
118 reset_times(_phase_times_sec, ARRAY_SIZE(_phase_times_sec));
119 reset_items(_phase_dead_items, ARRAY_SIZE(_phase_dead_items));
120 reset_items(_phase_total_items, ARRAY_SIZE(_phase_total_items));
121 if (_max_threads > 1) {
122 for (size_t i = 0; i < ARRAY_SIZE(_worker_data); ++i) {
123 _worker_data[i]->reset();
124 }
125 }
126}
127
128double WeakProcessorPhaseTimes::total_time_sec() const {
129 assert(is_initialized_time(_total_time_sec), "Total time not set");
130 return _total_time_sec;
131}
132
133void WeakProcessorPhaseTimes::record_total_time_sec(double time_sec) {
134 assert(!is_initialized_time(_total_time_sec), "Already set total time");
135 _total_time_sec = time_sec;
136}
137
138double WeakProcessorPhaseTimes::phase_time_sec(WeakProcessorPhase phase) const {
139 assert(is_initialized_time(_phase_times_sec[phase_index(phase)]),
140 "phase time not set %u", phase_index(phase));
141 return _phase_times_sec[phase_index(phase)];
142}
143
144void WeakProcessorPhaseTimes::record_phase_time_sec(WeakProcessorPhase phase, double time_sec) {
145 assert(!is_initialized_time(_phase_times_sec[phase_index(phase)]),
146 "Already set time for phase %u", phase_index(phase));
147 _phase_times_sec[phase_index(phase)] = time_sec;
148}
149
150void WeakProcessorPhaseTimes::record_phase_items(WeakProcessorPhase phase, size_t num_dead, size_t num_total) {
151 uint p = phase_index(phase);
152 assert(!is_initialized_items(_phase_dead_items[p]),
153 "Already set dead items for phase %u", p);
154 assert(!is_initialized_items(_phase_total_items[p]),
155 "Already set total items for phase %u", p);
156 _phase_dead_items[p] = num_dead;
157 _phase_total_items[p] = num_total;
158}
159
160WorkerDataArray<double>* WeakProcessorPhaseTimes::worker_data(WeakProcessorPhase phase) const {
161 assert_oop_storage_phase(phase);
162 assert(active_workers() > 1, "No worker data when single-threaded");
163 return _worker_data[WeakProcessorPhases::oop_storage_index(phase)];
164}
165
166double WeakProcessorPhaseTimes::worker_time_sec(uint worker_id, WeakProcessorPhase phase) const {
167 assert(worker_id < active_workers(),
168 "invalid worker id %u for %u", worker_id, active_workers());
169 if (active_workers() == 1) {
170 return phase_time_sec(phase);
171 } else {
172 return worker_data(phase)->get(worker_id);
173 }
174}
175
176void WeakProcessorPhaseTimes::record_worker_time_sec(uint worker_id,
177 WeakProcessorPhase phase,
178 double time_sec) {
179 if (active_workers() == 1) {
180 record_phase_time_sec(phase, time_sec);
181 } else {
182 worker_data(phase)->set(worker_id, time_sec);
183 }
184}
185
186void WeakProcessorPhaseTimes::record_worker_items(uint worker_id,
187 WeakProcessorPhase phase,
188 size_t num_dead,
189 size_t num_total) {
190 if (active_workers() == 1) {
191 record_phase_items(phase, num_dead, num_total);
192 } else {
193 worker_data(phase)->set_or_add_thread_work_item(worker_id, num_dead, DeadItems);
194 worker_data(phase)->set_or_add_thread_work_item(worker_id, num_total, TotalItems);
195 }
196}
197
198static double elapsed_time_sec(Ticks start_time, Ticks end_time) {
199 return (end_time - start_time).seconds();
200}
201
202WeakProcessorTimeTracker::WeakProcessorTimeTracker(WeakProcessorPhaseTimes* times) :
203 _times(times),
204 _start_time(Ticks::now())
205{}
206
207WeakProcessorTimeTracker::~WeakProcessorTimeTracker() {
208 if (_times != NULL) {
209 Ticks end_time = Ticks::now();
210 _times->record_total_time_sec(elapsed_time_sec(_start_time, end_time));
211 }
212}
213
214WeakProcessorPhaseTimeTracker::WeakProcessorPhaseTimeTracker(WeakProcessorPhaseTimes* times,
215 WeakProcessorPhase phase,
216 uint worker_id) :
217 _times(times),
218 _phase(phase),
219 _worker_id(worker_id),
220 _start_time(Ticks::now())
221{
222 assert_oop_storage_phase(_phase);
223 assert(_times == NULL || worker_id < _times->active_workers(),
224 "Invalid worker_id %u", worker_id);
225}
226
227WeakProcessorPhaseTimeTracker::WeakProcessorPhaseTimeTracker(WeakProcessorPhaseTimes* times,
228 WeakProcessorPhase phase) :
229 _times(times),
230 _phase(phase),
231 _worker_id(0),
232 _start_time(Ticks::now())
233{
234 assert(is_serial_phase(phase), "Not a serial phase %u", phase_index(phase));
235}
236
237WeakProcessorPhaseTimeTracker::~WeakProcessorPhaseTimeTracker() {
238 if (_times != NULL) {
239 double time_sec = elapsed_time_sec(_start_time, Ticks::now());
240 if (is_serial_phase(_phase)) {
241 _times->record_phase_time_sec(_phase, time_sec);
242 } else {
243 _times->record_worker_time_sec(_worker_id, _phase, time_sec);
244 }
245 }
246}
247
248//////////////////////////////////////////////////////////////////////////////
249// Printing times
250
251const char* const indents[] = {"", " ", " ", " ", " "};
252const size_t max_indents_index = ARRAY_SIZE(indents) - 1;
253
254static const char* indent_str(size_t i) {
255 return indents[MIN2(i, max_indents_index)];
256}
257
258#define TIME_FORMAT "%.1lfms"
259
260void WeakProcessorPhaseTimes::log_st_phase(WeakProcessorPhase phase,
261 uint indent) const {
262 log_debug(gc, phases)("%s%s: " TIME_FORMAT,
263 indent_str(indent),
264 WeakProcessorPhases::description(phase),
265 phase_time_sec(phase) * MILLIUNITS);
266
267 log_debug(gc, phases)("%s%s: " SIZE_FORMAT,
268 indent_str(indent + 1),
269 "Dead",
270 _phase_dead_items[phase_index(phase)]);
271
272 log_debug(gc, phases)("%s%s: " SIZE_FORMAT,
273 indent_str(indent + 1),
274 "Total",
275 _phase_total_items[phase_index(phase)]);
276}
277
278void WeakProcessorPhaseTimes::log_mt_phase_summary(WeakProcessorPhase phase,
279 uint indent) const {
280 LogTarget(Debug, gc, phases) lt;
281 LogStream ls(lt);
282 ls.print("%s", indents[indent]);
283 worker_data(phase)->print_summary_on(&ls, true);
284 log_mt_phase_details(worker_data(phase), indent + 1);
285
286 for (uint i = 0; i < worker_data(phase)->MaxThreadWorkItems; i++) {
287 WorkerDataArray<size_t>* work_items = worker_data(phase)->thread_work_items(i);
288 if (work_items != NULL) {
289 ls.print("%s", indents[indent + 1]);
290 work_items->print_summary_on(&ls, true);
291 log_mt_phase_details(work_items, indent + 1);
292 }
293 }
294}
295
296template <typename T>
297void WeakProcessorPhaseTimes::log_mt_phase_details(WorkerDataArray<T>* data,
298 uint indent) const {
299 LogTarget(Trace, gc, phases) lt;
300 if (lt.is_enabled()) {
301 LogStream ls(lt);
302 ls.print("%s", indents[indent]);
303 data->print_details_on(&ls);
304 }
305}
306
307void WeakProcessorPhaseTimes::log_print_phases(uint indent) const {
308 if (log_is_enabled(Debug, gc, phases)) {
309 FOR_EACH_WEAK_PROCESSOR_PHASE(phase) {
310 if (is_serial_phase(phase) || (active_workers() == 1)) {
311 log_st_phase(phase, indent);
312 } else {
313 log_mt_phase_summary(phase, indent);
314 }
315 }
316 }
317}
318
319void WeakProcessorPhaseTimes::log_print(uint indent) const {
320 if (log_is_enabled(Debug, gc, phases)) {
321 log_debug(gc, phases)("%s%s: " TIME_FORMAT,
322 indent_str(indent),
323 "Weak Processing",
324 total_time_sec() * MILLIUNITS);
325 log_print_phases(indent + 1);
326 }
327}
328