1 /*
2 * Copyright (c) 2017, 2018, 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/gcTimer.hpp"
27 #include "gc/shared/referenceProcessorPhaseTimes.hpp"
28 #include "gc/shared/referenceProcessor.inline.hpp"
29 #include "gc/shared/workerDataArray.inline.hpp"
30 #include "logging/log.hpp"
31 #include "logging/logStream.hpp"
32 #include "memory/allocation.inline.hpp"
33
34 RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers number,
35 ReferenceProcessorPhaseTimes* phase_times,
36 uint worker_id) :
37 _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) {
38 assert (phase_times != NULL, "Invariant");
39
40 _worker_time = phase_times->worker_time_sec(phase_times->par_phase(number));
41 }
42
43 RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcParPhases phase,
44 ReferenceProcessorPhaseTimes* phase_times,
45 uint worker_id) :
46 _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) {
47 assert (phase_times != NULL, "Invariant");
48
49 _worker_time = phase_times->worker_time_sec(phase);
50 }
51
52 RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker() {
53 _worker_time->set(_worker_id, os::elapsedTime() - _start_time);
54 }
55
56 RefProcPhaseTimeBaseTracker::RefProcPhaseTimeBaseTracker(const char* title,
57 ReferenceProcessorPhaseTimes* phase_times) :
58 _title(title), _phase_times(phase_times), _start_ticks(), _end_ticks() {
59 assert(_phase_times != NULL, "Invariant");
60
61 _start_ticks.stamp();
62 if (_phase_times->gc_timer() != NULL) {
63 _phase_times->gc_timer()->register_gc_phase_start(_title, _start_ticks);
64 }
65 }
66
67 static const char* phase_enum_2_phase_string(ReferenceProcessorPhaseTimes::RefProcParPhases phase) {
68 switch(phase) {
69 case ReferenceProcessorPhaseTimes::SoftRefPhase1:
70 return "Phase1";
71 case ReferenceProcessorPhaseTimes::SoftRefPhase2:
72 case ReferenceProcessorPhaseTimes::WeakRefPhase2:
73 case ReferenceProcessorPhaseTimes::FinalRefPhase2:
74 case ReferenceProcessorPhaseTimes::PhantomRefPhase2:
75 return "Phase2";
76 case ReferenceProcessorPhaseTimes::SoftRefPhase3:
77 case ReferenceProcessorPhaseTimes::WeakRefPhase3:
78 case ReferenceProcessorPhaseTimes::FinalRefPhase3:
79 case ReferenceProcessorPhaseTimes::PhantomRefPhase3:
80 return "Phase3";
81 default:
82 ShouldNotReachHere();
83 return NULL;
84 }
85 }
86
87 static const char* Indents[6] = {"", " ", " ", " ", " ", " "};
88
89 Ticks RefProcPhaseTimeBaseTracker::end_ticks() {
90 // If ASSERT is defined, the default value of Ticks will be -2.
91 if (_end_ticks.value() <= 0) {
92 _end_ticks.stamp();
93 }
94
95 return _end_ticks;
96 }
97
98 double RefProcPhaseTimeBaseTracker::elapsed_time() {
99 jlong end_value = end_ticks().value();
100
101 return TimeHelper::counter_to_millis(end_value - _start_ticks.value());
102 }
103
104 RefProcPhaseTimeBaseTracker::~RefProcPhaseTimeBaseTracker() {
105 if (_phase_times->gc_timer() != NULL) {
106 Ticks ticks = end_ticks();
107 _phase_times->gc_timer()->register_gc_phase_end(ticks);
108 }
109 }
110
111 RefProcBalanceQueuesTimeTracker::RefProcBalanceQueuesTimeTracker(ReferenceProcessorPhaseTimes* phase_times) :
112 RefProcPhaseTimeBaseTracker("Balance queues", phase_times) {}
113
114 RefProcBalanceQueuesTimeTracker::~RefProcBalanceQueuesTimeTracker() {
115 double elapsed = elapsed_time();
116 phase_times()->set_balance_queues_time_ms(phase_times()->processing_ref_type(), elapsed);
117 }
118
119 #define ASSERT_REF_TYPE(ref_type) assert(ref_type >= REF_SOFT && ref_type <= REF_PHANTOM, \
120 "Invariant (%d)", (int)ref_type)
121
122 #define ASSERT_PHASE_NUMBER(phase_number) assert(phase_number >= ReferenceProcessorPhaseTimes::RefPhase1 && \
123 phase_number <= ReferenceProcessorPhaseTimes::RefPhaseMax, \
124 "Invariant (%d)", phase_number);
125
126 static const char* phase_number_2_string(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers phase_number) {
127 ASSERT_PHASE_NUMBER(phase_number);
128
129 switch(phase_number) {
130 case ReferenceProcessorPhaseTimes::RefPhase1:
131 return "Phase1";
132 case ReferenceProcessorPhaseTimes::RefPhase2:
133 return "Phase2";
134 case ReferenceProcessorPhaseTimes::RefPhase3:
135 return "Phase3";
136 default:
137 ShouldNotReachHere();
138 return NULL;
139 }
140 }
141
142 RefProcParPhaseTimeTracker::RefProcParPhaseTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers phase_number,
143 ReferenceProcessorPhaseTimes* phase_times) :
144 _phase_number(phase_number),
145 RefProcPhaseTimeBaseTracker(phase_number_2_string(phase_number), phase_times) {}
146
147 RefProcParPhaseTimeTracker::~RefProcParPhaseTimeTracker() {
148 double elapsed = elapsed_time();
149 ReferenceProcessorPhaseTimes::RefProcParPhases phase = phase_times()->par_phase(_phase_number);
150 phase_times()->set_par_phase_time_ms(phase, elapsed);
151 }
152
153 static const char* ref_type_2_string(ReferenceType ref_type) {
154 ASSERT_REF_TYPE(ref_type);
155
156 switch(ref_type) {
157 case REF_SOFT:
158 return "SoftReference";
159 case REF_WEAK:
160 return "WeakReference";
161 case REF_FINAL:
162 return "FinalReference";
163 case REF_PHANTOM:
164 return "PhantomReference";
165 default:
166 ShouldNotReachHere();
167 return NULL;
168 }
169 }
170
171 RefProcPhaseTimesTracker::RefProcPhaseTimesTracker(ReferenceType ref_type,
172 ReferenceProcessorPhaseTimes* phase_times,
173 ReferenceProcessor* rp) :
174 _rp(rp), RefProcPhaseTimeBaseTracker(ref_type_2_string(ref_type), phase_times) {
175 phase_times->set_processing_ref_type(ref_type);
176
177 size_t discovered = rp->total_reference_count(ref_type);
178 phase_times->set_ref_discovered(ref_type, discovered);
179 }
180
181 RefProcPhaseTimesTracker::~RefProcPhaseTimesTracker() {
182 double elapsed = elapsed_time();
183 ReferenceProcessorPhaseTimes* times = phase_times();
184 ReferenceType ref_type = times->processing_ref_type();
185 times->set_ref_proc_time_ms(ref_type, elapsed);
186
187 size_t after_count = _rp->total_reference_count(ref_type);
188 size_t discovered = times->ref_discovered(ref_type);
189 times->set_ref_cleared(ref_type, discovered - after_count);
190 }
191
192 ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(GCTimer* gc_timer, uint max_gc_threads) :
193 _gc_timer(gc_timer), _processing_is_mt(false) {
194
195 for (int i = 0; i < RefParPhaseMax; i++) {
196 _worker_time_sec[i] = new WorkerDataArray<double>(max_gc_threads, "Process lists (ms)");
197 _par_phase_time_ms[i] = uninitialized();
198 }
199
200 for (int i = 0; i < number_of_subclasses_of_ref; i++) {
201 _ref_proc_time_ms[i] = uninitialized();
202 _balance_queues_time_ms[i] = uninitialized();
203 _ref_cleared[i] = 0;
204 _ref_discovered[i] = 0;
205 _ref_enqueued[i] = 0;
206 }
207 }
208
209 inline int ref_type_2_index(ReferenceType ref_type) {
210 return ref_type - REF_SOFT;
211 }
212
213 #define ASSERT_PAR_PHASE(phase) assert(phase >= ReferenceProcessorPhaseTimes::SoftRefPhase1 && \
214 phase < ReferenceProcessorPhaseTimes::RefParPhaseMax, \
215 "Invariant (%d)", (int)phase);
216
217 WorkerDataArray<double>* ReferenceProcessorPhaseTimes::worker_time_sec(RefProcParPhases par_phase) const {
218 ASSERT_PAR_PHASE(par_phase);
219 return _worker_time_sec[par_phase];
220 }
221
222 double ReferenceProcessorPhaseTimes::par_phase_time_ms(RefProcParPhases par_phase) const {
223 ASSERT_PAR_PHASE(par_phase);
224 return _par_phase_time_ms[par_phase];
225 }
226
227 void ReferenceProcessorPhaseTimes::set_par_phase_time_ms(RefProcParPhases par_phase,
228 double par_phase_time_ms) {
229 ASSERT_PAR_PHASE(par_phase);
230 _par_phase_time_ms[par_phase] = par_phase_time_ms;
231 }
232
233 void ReferenceProcessorPhaseTimes::reset() {
234 for (int i = 0; i < RefParPhaseMax; i++) {
235 _worker_time_sec[i]->reset();
236 _par_phase_time_ms[i] = uninitialized();
237 }
238
239 for (int i = 0; i < number_of_subclasses_of_ref; i++) {
240 _ref_proc_time_ms[i] = uninitialized();
241 _balance_queues_time_ms[i] = uninitialized();
242 _ref_cleared[i] = 0;
243 _ref_discovered[i] = 0;
244 _ref_enqueued[i] = 0;
245 }
246
247 _total_time_ms = uninitialized();
248
249 _processing_is_mt = false;
250 }
251
252 ReferenceProcessorPhaseTimes::~ReferenceProcessorPhaseTimes() {
253 for (int i = 0; i < RefParPhaseMax; i++) {
254 delete _worker_time_sec[i];
255 }
256 }
257
258 double ReferenceProcessorPhaseTimes::ref_proc_time_ms(ReferenceType ref_type) const {
259 ASSERT_REF_TYPE(ref_type);
260 return _ref_proc_time_ms[ref_type_2_index(ref_type)];
261 }
262
263 void ReferenceProcessorPhaseTimes::set_ref_proc_time_ms(ReferenceType ref_type,
264 double ref_proc_time_ms) {
265 ASSERT_REF_TYPE(ref_type);
266 _ref_proc_time_ms[ref_type_2_index(ref_type)] = ref_proc_time_ms;
267 }
268
269 size_t ReferenceProcessorPhaseTimes::ref_cleared(ReferenceType ref_type) const {
270 ASSERT_REF_TYPE(ref_type);
271 return _ref_cleared[ref_type_2_index(ref_type)];
272 }
273
274 void ReferenceProcessorPhaseTimes::set_ref_cleared(ReferenceType ref_type, size_t count) {
275 ASSERT_REF_TYPE(ref_type);
276 _ref_cleared[ref_type_2_index(ref_type)] = count;
277 }
278
279 size_t ReferenceProcessorPhaseTimes::ref_discovered(ReferenceType ref_type) const {
280 ASSERT_REF_TYPE(ref_type);
281 return _ref_discovered[ref_type_2_index(ref_type)];
282 }
283
284 void ReferenceProcessorPhaseTimes::set_ref_discovered(ReferenceType ref_type, size_t count) {
285 ASSERT_REF_TYPE(ref_type);
286 _ref_discovered[ref_type_2_index(ref_type)] = count;
287 }
288
289 size_t ReferenceProcessorPhaseTimes::ref_enqueued(ReferenceType ref_type) const {
290 ASSERT_REF_TYPE(ref_type);
291 return _ref_enqueued[ref_type_2_index(ref_type)];
292 }
293
294 void ReferenceProcessorPhaseTimes::set_ref_enqueued(ReferenceType ref_type, size_t count) {
295 ASSERT_REF_TYPE(ref_type);
296 _ref_enqueued[ref_type_2_index(ref_type)] = count;
297 }
298
299 double ReferenceProcessorPhaseTimes::balance_queues_time_ms(ReferenceType ref_type) const {
300 ASSERT_REF_TYPE(ref_type);
301 return _balance_queues_time_ms[ref_type_2_index(ref_type)];
302 }
303
304 void ReferenceProcessorPhaseTimes::set_balance_queues_time_ms(ReferenceType ref_type, double time_ms) {
305 ASSERT_REF_TYPE(ref_type);
306 _balance_queues_time_ms[ref_type_2_index(ref_type)] = time_ms;
307 }
308
309 ReferenceProcessorPhaseTimes::RefProcParPhases
310 ReferenceProcessorPhaseTimes::par_phase(RefProcPhaseNumbers phase_number) const {
311 ASSERT_PHASE_NUMBER(phase_number);
312 ASSERT_REF_TYPE(_processing_ref_type);
313
314 int result = SoftRefPhase1;
315
316 switch(_processing_ref_type) {
317 case REF_SOFT:
318 result = (int)SoftRefPhase1;
319 result += phase_number;
320
321 assert((RefProcParPhases)result >= SoftRefPhase1 &&
322 (RefProcParPhases)result <= SoftRefPhase3,
323 "Invariant (%d)", result);
324 break;
325 case REF_WEAK:
326 result = (int)WeakRefPhase2;
327 result += (phase_number - 1);
328 assert((RefProcParPhases)result >= WeakRefPhase2 &&
329 (RefProcParPhases)result <= WeakRefPhase3,
330 "Invariant (%d)", result);
331 break;
332 case REF_FINAL:
333 result = (int)FinalRefPhase2;
334 result += (phase_number - 1);
335 assert((RefProcParPhases)result >= FinalRefPhase2 &&
336 (RefProcParPhases)result <= FinalRefPhase3,
337 "Invariant (%d)", result);
338 break;
339 case REF_PHANTOM:
340 result = (int)PhantomRefPhase2;
341 result += (phase_number - 1);
342 assert((RefProcParPhases)result >= PhantomRefPhase2 &&
343 (RefProcParPhases)result <= PhantomRefPhase3,
344 "Invariant (%d)", result);
345 break;
346 default:
347 ShouldNotReachHere();
348 }
349
350 ASSERT_PAR_PHASE(result);
351
352 return (RefProcParPhases)result;
353 }
354
355 #define TIME_FORMAT "%.1lfms"
356
357 void ReferenceProcessorPhaseTimes::print_all_references(uint base_indent, bool print_total) const {
358 if (print_total) {
359 LogTarget(Debug, gc, phases, ref) lt;
360
361 if (lt.is_enabled()) {
362 LogStream ls(lt);
363 ls.print_cr("%s%s: " TIME_FORMAT,
364 Indents[base_indent], "Reference Processing", total_time_ms());
365 }
366 }
367
368 uint next_indent = base_indent + 1;
369 print_reference(REF_SOFT, next_indent);
370 print_reference(REF_WEAK, next_indent);
371 print_reference(REF_FINAL, next_indent);
372 print_reference(REF_PHANTOM, next_indent);
373 }
374
375 void ReferenceProcessorPhaseTimes::print_reference(ReferenceType ref_type, uint base_indent) const {
376 LogTarget(Debug, gc, phases, ref) lt;
377
378 if (lt.is_enabled()) {
379 LogStream ls(lt);
380 uint next_indent = base_indent + 1;
381 ResourceMark rm;
382
383 ls.print_cr("%s%s: " TIME_FORMAT,
384 Indents[base_indent], ref_type_2_string(ref_type), ref_proc_time_ms(ref_type));
385
386 double balance_time = balance_queues_time_ms(ref_type);
387 if (balance_time != uninitialized()) {
388 ls.print_cr("%s%s " TIME_FORMAT, Indents[next_indent], "Balance queues:", balance_time);
389 }
390
391 switch(ref_type) {
392 case REF_SOFT:
393 print_phase(SoftRefPhase1, next_indent);
394 print_phase(SoftRefPhase2, next_indent);
395 print_phase(SoftRefPhase3, next_indent);
396 break;
397
398 case REF_WEAK:
399 print_phase(WeakRefPhase2, next_indent);
400 print_phase(WeakRefPhase3, next_indent);
401 break;
402
403 case REF_FINAL:
404 print_phase(FinalRefPhase2, next_indent);
405 print_phase(FinalRefPhase3, next_indent);
406 break;
407
408 case REF_PHANTOM:
409 print_phase(PhantomRefPhase2, next_indent);
410 print_phase(PhantomRefPhase3, next_indent);
411 break;
412
413 default:
414 ShouldNotReachHere();
415 }
416
417 ls.print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Discovered:", ref_discovered(ref_type));
418 ls.print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Cleared:", ref_cleared(ref_type));
419 }
420 }
421
422 void ReferenceProcessorPhaseTimes::print_phase(RefProcParPhases phase, uint indent) const {
423 double phase_time = par_phase_time_ms(phase);
424 if (phase_time != uninitialized()) {
425 LogTarget(Debug, gc, phases, ref) lt;
426
427 LogStream ls(lt);
428
429 ls.print_cr("%s%s%s " TIME_FORMAT,
430 Indents[indent],
431 phase_enum_2_phase_string(phase),
432 indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */
433 phase_time);
434
435 LogTarget(Trace, gc, phases, ref) lt2;
436 if (_processing_is_mt && lt2.is_enabled()) {
437 LogStream ls(lt2);
438
439 ls.print("%s", Indents[indent + 1]);
440 // worker_time_sec is recorded in seconds but it will be printed in milliseconds.
441 worker_time_sec(phase)->print_summary_on(&ls, true);
442 }
443 }
444 }
445
446 #undef ASSERT_REF_TYPE
447 #undef ASSERT_PHASE_NUMBER
448 #undef ASSERT_PAR_PHASE
449 #undef TIME_FORMAT