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