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#define ASSERT_REF_TYPE(ref_type) assert((ref_type) >= REF_SOFT && (ref_type) <= REF_PHANTOM, \
35 "Invariant (%d)", (int)ref_type)
36
37#define ASSERT_PHASE(phase) assert((phase) >= ReferenceProcessor::RefPhase1 && \
38 (phase) < ReferenceProcessor::RefPhaseMax, \
39 "Invariant (%d)", (int)phase);
40
41#define ASSERT_SUB_PHASE(phase) assert((phase) >= ReferenceProcessor::SoftRefSubPhase1 && \
42 (phase) < ReferenceProcessor::RefSubPhaseMax, \
43 "Invariant (%d)", (int)phase);
44
45static const char* SubPhasesParWorkTitle[ReferenceProcessor::RefSubPhaseMax] = {
46 "SoftRef (ms):",
47 "SoftRef (ms):",
48 "WeakRef (ms):",
49 "FinalRef (ms):",
50 "FinalRef (ms):",
51 "PhantomRef (ms):"
52 };
53
54static const char* Phase2ParWorkTitle = "Total (ms):";
55
56static const char* SubPhasesSerWorkTitle[ReferenceProcessor::RefSubPhaseMax] = {
57 "SoftRef:",
58 "SoftRef:",
59 "WeakRef:",
60 "FinalRef:",
61 "FinalRef:",
62 "PhantomRef:"
63 };
64
65static const char* Phase2SerWorkTitle = "Total:";
66
67static const char* Indents[6] = {"", " ", " ", " ", " ", " "};
68
69static const char* PhaseNames[ReferenceProcessor::RefPhaseMax] = {
70 "Reconsider SoftReferences",
71 "Notify Soft/WeakReferences",
72 "Notify and keep alive finalizable",
73 "Notify PhantomReferences"
74 };
75
76static const char* ReferenceTypeNames[REF_PHANTOM + 1] = {
77 "None", "Other", "SoftReference", "WeakReference", "FinalReference", "PhantomReference"
78 };
79
80STATIC_ASSERT((REF_PHANTOM + 1) == ARRAY_SIZE(ReferenceTypeNames));
81
82static const char* phase_enum_2_phase_string(ReferenceProcessor::RefProcPhases phase) {
83 ASSERT_PHASE(phase);
84 return PhaseNames[phase];
85}
86
87static const char* ref_type_2_string(ReferenceType ref_type) {
88 ASSERT_REF_TYPE(ref_type);
89 return ReferenceTypeNames[ref_type];
90}
91
92RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(WorkerDataArray<double>* worker_time, uint worker_id) :
93 _worker_time(worker_time), _start_time(os::elapsedTime()), _worker_id(worker_id) {
94 assert(worker_time != NULL, "Invariant");
95}
96
97RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker() {
98 double result = os::elapsedTime() - _start_time;
99 _worker_time->set(_worker_id, result);
100}
101
102RefProcSubPhasesWorkerTimeTracker::RefProcSubPhasesWorkerTimeTracker(ReferenceProcessor::RefProcSubPhases phase,
103 ReferenceProcessorPhaseTimes* phase_times,
104 uint worker_id) :
105 RefProcWorkerTimeTracker(phase_times->sub_phase_worker_time_sec(phase), worker_id) {
106}
107
108RefProcSubPhasesWorkerTimeTracker::~RefProcSubPhasesWorkerTimeTracker() {
109}
110
111RefProcPhaseTimeBaseTracker::RefProcPhaseTimeBaseTracker(const char* title,
112 ReferenceProcessor::RefProcPhases phase_number,
113 ReferenceProcessorPhaseTimes* phase_times) :
114 _phase_times(phase_times), _start_ticks(), _end_ticks(), _phase_number(phase_number) {
115 assert(_phase_times != NULL, "Invariant");
116
117 _start_ticks.stamp();
118 if (_phase_times->gc_timer() != NULL) {
119 _phase_times->gc_timer()->register_gc_phase_start(title, _start_ticks);
120 }
121}
122
123Ticks RefProcPhaseTimeBaseTracker::end_ticks() {
124 // If ASSERT is defined, the default value of Ticks will be -2.
125 if (_end_ticks.value() <= 0) {
126 _end_ticks.stamp();
127 }
128
129 return _end_ticks;
130}
131
132double RefProcPhaseTimeBaseTracker::elapsed_time() {
133 jlong end_value = end_ticks().value();
134
135 return TimeHelper::counter_to_millis(end_value - _start_ticks.value());
136}
137
138RefProcPhaseTimeBaseTracker::~RefProcPhaseTimeBaseTracker() {
139 if (_phase_times->gc_timer() != NULL) {
140 Ticks ticks = end_ticks();
141 _phase_times->gc_timer()->register_gc_phase_end(ticks);
142 }
143}
144
145RefProcBalanceQueuesTimeTracker::RefProcBalanceQueuesTimeTracker(ReferenceProcessor::RefProcPhases phase_number,
146 ReferenceProcessorPhaseTimes* phase_times) :
147 RefProcPhaseTimeBaseTracker("Balance queues", phase_number, phase_times) {}
148
149RefProcBalanceQueuesTimeTracker::~RefProcBalanceQueuesTimeTracker() {
150 double elapsed = elapsed_time();
151 phase_times()->set_balance_queues_time_ms(_phase_number, elapsed);
152}
153
154RefProcPhaseTimeTracker::RefProcPhaseTimeTracker(ReferenceProcessor::RefProcPhases phase_number,
155 ReferenceProcessorPhaseTimes* phase_times) :
156 RefProcPhaseTimeBaseTracker(phase_enum_2_phase_string(phase_number), phase_number, phase_times) {
157}
158
159RefProcPhaseTimeTracker::~RefProcPhaseTimeTracker() {
160 double elapsed = elapsed_time();
161 phase_times()->set_phase_time_ms(_phase_number, elapsed);
162}
163
164RefProcTotalPhaseTimesTracker::RefProcTotalPhaseTimesTracker(ReferenceProcessor::RefProcPhases phase_number,
165 ReferenceProcessorPhaseTimes* phase_times,
166 ReferenceProcessor* rp) :
167 RefProcPhaseTimeBaseTracker(phase_enum_2_phase_string(phase_number), phase_number, phase_times), _rp(rp) {
168}
169
170RefProcTotalPhaseTimesTracker::~RefProcTotalPhaseTimesTracker() {
171 double elapsed = elapsed_time();
172 phase_times()->set_phase_time_ms(_phase_number, elapsed);
173}
174
175ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(GCTimer* gc_timer, uint max_gc_threads) :
176 _processing_is_mt(false), _gc_timer(gc_timer) {
177
178 for (uint i = 0; i < ReferenceProcessor::RefSubPhaseMax; i++) {
179 _sub_phases_worker_time_sec[i] = new WorkerDataArray<double>(max_gc_threads, SubPhasesParWorkTitle[i]);
180 }
181 _phase2_worker_time_sec = new WorkerDataArray<double>(max_gc_threads, Phase2ParWorkTitle);
182
183 reset();
184}
185
186inline int ref_type_2_index(ReferenceType ref_type) {
187 return ref_type - REF_SOFT;
188}
189
190WorkerDataArray<double>* ReferenceProcessorPhaseTimes::sub_phase_worker_time_sec(ReferenceProcessor::RefProcSubPhases sub_phase) const {
191 ASSERT_SUB_PHASE(sub_phase);
192 return _sub_phases_worker_time_sec[sub_phase];
193}
194
195double ReferenceProcessorPhaseTimes::phase_time_ms(ReferenceProcessor::RefProcPhases phase) const {
196 ASSERT_PHASE(phase);
197 return _phases_time_ms[phase];
198}
199
200void ReferenceProcessorPhaseTimes::set_phase_time_ms(ReferenceProcessor::RefProcPhases phase,
201 double phase_time_ms) {
202 ASSERT_PHASE(phase);
203 _phases_time_ms[phase] = phase_time_ms;
204}
205
206void ReferenceProcessorPhaseTimes::reset() {
207 for (int i = 0; i < ReferenceProcessor::RefSubPhaseMax; i++) {
208 _sub_phases_worker_time_sec[i]->reset();
209 _sub_phases_total_time_ms[i] = uninitialized();
210 }
211
212 for (int i = 0; i < ReferenceProcessor::RefPhaseMax; i++) {
213 _phases_time_ms[i] = uninitialized();
214 _balance_queues_time_ms[i] = uninitialized();
215 }
216
217 _phase2_worker_time_sec->reset();
218
219 for (int i = 0; i < number_of_subclasses_of_ref; i++) {
220 _ref_cleared[i] = 0;
221 _ref_discovered[i] = 0;
222 }
223
224 _total_time_ms = uninitialized();
225
226 _processing_is_mt = false;
227}
228
229ReferenceProcessorPhaseTimes::~ReferenceProcessorPhaseTimes() {
230 for (int i = 0; i < ReferenceProcessor::RefSubPhaseMax; i++) {
231 delete _sub_phases_worker_time_sec[i];
232 }
233 delete _phase2_worker_time_sec;
234}
235
236double ReferenceProcessorPhaseTimes::sub_phase_total_time_ms(ReferenceProcessor::RefProcSubPhases sub_phase) const {
237 ASSERT_SUB_PHASE(sub_phase);
238 return _sub_phases_total_time_ms[sub_phase];
239}
240
241void ReferenceProcessorPhaseTimes::set_sub_phase_total_phase_time_ms(ReferenceProcessor::RefProcSubPhases sub_phase,
242 double time_ms) {
243 ASSERT_SUB_PHASE(sub_phase);
244 _sub_phases_total_time_ms[sub_phase] = time_ms;
245}
246
247void ReferenceProcessorPhaseTimes::add_ref_cleared(ReferenceType ref_type, size_t count) {
248 ASSERT_REF_TYPE(ref_type);
249 Atomic::add(count, &_ref_cleared[ref_type_2_index(ref_type)]);
250}
251
252void ReferenceProcessorPhaseTimes::set_ref_discovered(ReferenceType ref_type, size_t count) {
253 ASSERT_REF_TYPE(ref_type);
254 _ref_discovered[ref_type_2_index(ref_type)] = count;
255}
256
257double ReferenceProcessorPhaseTimes::balance_queues_time_ms(ReferenceProcessor::RefProcPhases phase) const {
258 ASSERT_PHASE(phase);
259 return _balance_queues_time_ms[phase];
260}
261
262void ReferenceProcessorPhaseTimes::set_balance_queues_time_ms(ReferenceProcessor::RefProcPhases phase, double time_ms) {
263 ASSERT_PHASE(phase);
264 _balance_queues_time_ms[phase] = time_ms;
265}
266
267#define TIME_FORMAT "%.1lfms"
268
269void ReferenceProcessorPhaseTimes::print_all_references(uint base_indent, bool print_total) const {
270 if (print_total) {
271 LogTarget(Debug, gc, phases, ref) lt;
272
273 if (lt.is_enabled()) {
274 LogStream ls(lt);
275 ls.print_cr("%s%s: " TIME_FORMAT,
276 Indents[base_indent], "Reference Processing", total_time_ms());
277 }
278 }
279
280 uint next_indent = base_indent + 1;
281 print_phase(ReferenceProcessor::RefPhase1, next_indent);
282 print_phase(ReferenceProcessor::RefPhase2, next_indent);
283 print_phase(ReferenceProcessor::RefPhase3, next_indent);
284 print_phase(ReferenceProcessor::RefPhase4, next_indent);
285
286 print_reference(REF_SOFT, next_indent);
287 print_reference(REF_WEAK, next_indent);
288 print_reference(REF_FINAL, next_indent);
289 print_reference(REF_PHANTOM, next_indent);
290
291}
292
293void ReferenceProcessorPhaseTimes::print_reference(ReferenceType ref_type, uint base_indent) const {
294 LogTarget(Debug, gc, phases, ref) lt;
295
296 if (lt.is_enabled()) {
297 LogStream ls(lt);
298 ResourceMark rm;
299
300 ls.print_cr("%s%s:", Indents[base_indent], ref_type_2_string(ref_type));
301
302 uint const next_indent = base_indent + 1;
303 int const ref_type_index = ref_type_2_index(ref_type);
304
305 ls.print_cr("%sDiscovered: " SIZE_FORMAT, Indents[next_indent], _ref_discovered[ref_type_index]);
306 ls.print_cr("%sCleared: " SIZE_FORMAT, Indents[next_indent], _ref_cleared[ref_type_index]);
307 }
308}
309
310void ReferenceProcessorPhaseTimes::print_phase(ReferenceProcessor::RefProcPhases phase, uint indent) const {
311 double phase_time = phase_time_ms(phase);
312
313 if (phase_time == uninitialized()) {
314 return;
315 }
316
317 LogTarget(Debug, gc, phases, ref) lt;
318 LogStream ls(lt);
319
320 ls.print_cr("%s%s%s " TIME_FORMAT,
321 Indents[indent],
322 phase_enum_2_phase_string(phase),
323 indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */
324 phase_time);
325
326 LogTarget(Debug, gc, phases, ref) lt2;
327 if (lt2.is_enabled()) {
328 LogStream ls(lt2);
329
330 if (_processing_is_mt) {
331 print_balance_time(&ls, phase, indent + 1);
332 }
333
334 switch (phase) {
335 case ReferenceProcessor::RefPhase1:
336 print_sub_phase(&ls, ReferenceProcessor::SoftRefSubPhase1, indent + 1);
337 break;
338 case ReferenceProcessor::RefPhase2:
339 print_sub_phase(&ls, ReferenceProcessor::SoftRefSubPhase2, indent + 1);
340 print_sub_phase(&ls, ReferenceProcessor::WeakRefSubPhase2, indent + 1);
341 print_sub_phase(&ls, ReferenceProcessor::FinalRefSubPhase2, indent + 1);
342 break;
343 case ReferenceProcessor::RefPhase3:
344 print_sub_phase(&ls, ReferenceProcessor::FinalRefSubPhase3, indent + 1);
345 break;
346 case ReferenceProcessor::RefPhase4:
347 print_sub_phase(&ls, ReferenceProcessor::PhantomRefSubPhase4, indent + 1);
348 break;
349 default:
350 ShouldNotReachHere();
351 }
352 if (phase == ReferenceProcessor::RefPhase2) {
353 print_worker_time(&ls, _phase2_worker_time_sec, Phase2SerWorkTitle, indent + 1);
354 }
355 }
356}
357
358void ReferenceProcessorPhaseTimes::print_balance_time(LogStream* ls, ReferenceProcessor::RefProcPhases phase, uint indent) const {
359 double balance_time = balance_queues_time_ms(phase);
360 if (balance_time != uninitialized()) {
361 ls->print_cr("%s%s " TIME_FORMAT, Indents[indent], "Balance queues:", balance_time);
362 }
363}
364
365void ReferenceProcessorPhaseTimes::print_sub_phase(LogStream* ls, ReferenceProcessor::RefProcSubPhases sub_phase, uint indent) const {
366 print_worker_time(ls, _sub_phases_worker_time_sec[sub_phase], SubPhasesSerWorkTitle[sub_phase], indent);
367}
368
369void ReferenceProcessorPhaseTimes::print_worker_time(LogStream* ls, WorkerDataArray<double>* worker_time, const char* ser_title, uint indent) const {
370 ls->print("%s", Indents[indent]);
371 if (_processing_is_mt) {
372 worker_time->print_summary_on(ls, true);
373 LogTarget(Trace, gc, phases, task) lt;
374 if (lt.is_enabled()) {
375 LogStream ls2(lt);
376 ls2.print("%s", Indents[indent]);
377 worker_time->print_details_on(&ls2);
378 }
379 } else {
380 if (worker_time->get(0) != uninitialized()) {
381 ls->print_cr("%s " TIME_FORMAT,
382 ser_title,
383 worker_time->get(0) * MILLIUNITS);
384 } else {
385 ls->print_cr("%s skipped", ser_title);
386 }
387 }
388}
389
390#undef ASSERT_REF_TYPE
391#undef ASSERT_SUB_PHASE
392#undef ASSERT_PHASE
393#undef TIME_FORMAT
394