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