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