1 /*
2 * Copyright (c) 2017, 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 "logging/log.hpp"
30
31 RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(WorkerDataArray<double>* worker_time, uint worker_id) :
32 _worker_time(worker_time), _start_time(0.0), _worker_id(worker_id) {
33 if (_worker_time != NULL) {
34 _start_time = os::elapsedTime();
35 }
36 }
37
38 RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker() {
39 if (_worker_time != NULL) {
40 _worker_time->set(_worker_id, os::elapsedTime() - _start_time);
41 }
42 }
43
44 static size_t total_count_from_list(DiscoveredList lists[], uint max_num_q) {
45 size_t total = 0;
46 for (uint i = 0; i < max_num_q; ++i) {
47 total += lists[i].length();
48 }
49 return total;
50 }
51
52 RefProcPhaseTimeBaseTracker::RefProcPhaseTimeBaseTracker(const char* title,
53 ReferenceProcessorPhaseTimes* phase_times,
54 GCTimer* gc_timer) :
55 _title(title), _phase_times(phase_times), _start_ticks(), _end_ticks(), _gc_timer(gc_timer) {
56 assert(_phase_times != NULL, "Invariant");
57
58 _start_ticks.stamp();
59 if (_gc_timer != NULL) {
60 _gc_timer->register_gc_phase_start(_title, _start_ticks);
61 }
62 }
63
64 static const char* phase_enum_2_string(ReferenceProcessorPhaseTimes::RefProcPhases phase) {
65 switch(phase) {
66 case ReferenceProcessorPhaseTimes::RefPhase1:
67 return "Phase1";
68 case ReferenceProcessorPhaseTimes::RefPhase2:
69 return "Phase2";
70 case ReferenceProcessorPhaseTimes::RefPhase3:
71 return "Phase3";
72 case ReferenceProcessorPhaseTimes::RefEnqueue:
73 return "Enqueue reference lists";
74 default:
75 ShouldNotReachHere();
76 return NULL;
77 }
78 }
79
80 static const char* Indents[5] = {"", " ", " ", " ", " "};
81
82 void RefProcPhaseTimeBaseTracker::print_phase(ReferenceProcessorPhaseTimes::RefProcPhases phase, uint indent) {
83 double phase_time = phase_times()->phase_time_ms(phase);
84 if (phase_time != ReferenceProcessorPhaseTimes::uninitialized()) {
85 Log(gc, ref) log;
86
87 log.debug_stream()->print_cr("%s%s%s %0.3fms",
88 Indents[indent],
89 phase_enum_2_string(phase),
90 indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */
91 phase_time);
92 if (phase_times()->processing_is_mt() && log.is_level(LogLevel::Trace)) {
93 outputStream* out = log.trace_stream();
94
95 out->print("%s", Indents[2]);
96 // worker_time_sec is recorded in seconds but it will be printed in milliseconds.
97 phase_times()->worker_time_sec(phase)->print_summary_on(out, true);
98 }
99 }
100 }
101
102 Ticks RefProcPhaseTimeBaseTracker::end_ticks() {
103 // If ASSERT is defined, the default value of Ticks will be -2.
104 if (_end_ticks.value() <= 0) {
105 _end_ticks.stamp();
106 }
107
108 return _end_ticks;
109 }
110
111 double RefProcPhaseTimeBaseTracker::elapsed_time() {
112 jlong end_value = end_ticks().value();
113
114 return TimeHelper::counter_to_millis(end_value - _start_ticks.value());
115 }
116
117 RefProcPhaseTimeBaseTracker::~RefProcPhaseTimeBaseTracker() {
118 if (_gc_timer != NULL) {
119 Ticks ticks = end_ticks();
120 _gc_timer->register_gc_phase_end(ticks);
121 }
122 }
123
124 RefProcBalanceQueuesTimeTracker::RefProcBalanceQueuesTimeTracker(ReferenceProcessorPhaseTimes* phase_times,
125 GCTimer* gc_timer) :
126 RefProcPhaseTimeBaseTracker("Balance queues", phase_times, gc_timer) {}
127
128 RefProcBalanceQueuesTimeTracker::~RefProcBalanceQueuesTimeTracker() {
129 double elapsed = elapsed_time();
130 phase_times()->set_balance_queues_time_ms(elapsed);
131 }
132
133 RefProcPhaseTimeTracker::RefProcPhaseTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhases phase,
134 ReferenceProcessorPhaseTimes* phase_times,
135 GCTimer* gc_timer) :
136 _phase(phase), RefProcPhaseTimeBaseTracker(phase_enum_2_string(phase), phase_times, gc_timer) {}
137
138 RefProcPhaseTimeTracker::~RefProcPhaseTimeTracker() {
139 double elapsed = elapsed_time();
140 phase_times()->set_phase_time_ms(_phase, elapsed);
141 }
142
143 RefProcPhaseTimesLogger::RefProcPhaseTimesLogger(const char* title,
144 ReferenceProcessorPhaseTimes* times,
145 DiscoveredList lists[],
146 GCTimer* gc_timer) :
147 _lists(lists), RefProcPhaseTimeBaseTracker(title, times, gc_timer) {
148 _ref_discovered = total_count_from_list(_lists, phase_times()->max_gc_threads());
149 }
150
151 RefProcPhaseTimesLogger::~RefProcPhaseTimesLogger() {
152 double elapsed = elapsed_time();
153
154 Log(gc, ref) log;
155
156 if (log.is_level(LogLevel::Debug)) {
157 outputStream* out = log.debug_stream();
158 ResourceMark rm;
159
160 out->print_cr("%s %0.3fms", _title, elapsed);
161
162 double balance_time = phase_times()->balance_queues_time_ms();
163 if (balance_time != ReferenceProcessorPhaseTimes::uninitialized()) {
164 out->print_cr(" %s %0.3fms", "Balance queues:", balance_time);
165 }
166
167 // Print stats
168 print_phase(ReferenceProcessorPhaseTimes::RefPhase1, 1);
169 print_phase(ReferenceProcessorPhaseTimes::RefPhase2, 1);
170 print_phase(ReferenceProcessorPhaseTimes::RefPhase3, 1);
171
172 size_t after_count = total_count_from_list(_lists, phase_times()->max_gc_threads());
173 out->print_cr(" %s " SIZE_FORMAT, "Cleared:", _ref_discovered - after_count);
174 out->print_cr(" %s " SIZE_FORMAT, "Discovered:", _ref_discovered);
175 }
176
177 // Reset for next use.
178 phase_times()->reset();
179 }
180
181 RefProcEnqueueTimeLogger::RefProcEnqueueTimeLogger(ReferenceProcessorPhaseTimes* phase_times,
182 ReferenceProcessorStats& stats,
183 GCTimer* gc_timer) :
184 _stats(stats), RefProcPhaseTimeBaseTracker("Enqueue reference lists", phase_times, gc_timer) {}
185
186 RefProcEnqueueTimeLogger::~RefProcEnqueueTimeLogger() {
187 double elapsed = elapsed_time();
188
189 phase_times()->set_phase_time_ms(ReferenceProcessorPhaseTimes::RefEnqueue, elapsed);
190
191 print_phase(ReferenceProcessorPhaseTimes::RefEnqueue, 0);
192 phase_times()->reset();
193
194 log_debug(gc, ref)(" Ref Counts: Soft: " SIZE_FORMAT " Weak: " SIZE_FORMAT
195 " Final: " SIZE_FORMAT " Phantom: " SIZE_FORMAT ,
196 _stats.soft_count(), _stats.weak_count(),
197 _stats.final_count(), _stats.phantom_count());
198 }
199
200 ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(uint max_gc_threads, bool processing_is_mt) :
201 _balance_queues_time_ms(uninitialized()), _max_gc_threads(max_gc_threads), _processing_is_mt(processing_is_mt) {
202
203 _worker_time_sec[RefPhase1] = new WorkerDataArray<double>(_max_gc_threads, "Process lists (ms)");
204 _worker_time_sec[RefPhase2] = new WorkerDataArray<double>(_max_gc_threads, "Process lists (ms)");
205 _worker_time_sec[RefPhase3] = new WorkerDataArray<double>(_max_gc_threads, "Process lists (ms)");
206 _worker_time_sec[RefEnqueue] = new WorkerDataArray<double>(_max_gc_threads, "Process lists (ms)");
207
208 _phase_time_ms[RefPhase1] = uninitialized();
209 _phase_time_ms[RefPhase2] = uninitialized();
210 _phase_time_ms[RefPhase3] = uninitialized();
211 _phase_time_ms[RefEnqueue] = uninitialized();
212 }
213
214 WorkerDataArray<double>* ReferenceProcessorPhaseTimes::worker_time_sec(RefProcPhases phase) const {
215 assert(phase >= RefPhase1 && phase < RefPhaseMax, "Invariant");
216 return _worker_time_sec[phase];
217 }
218
219 double ReferenceProcessorPhaseTimes::phase_time_ms(RefProcPhases phase) const {
220 assert(phase >= RefPhase1 && phase < RefPhaseMax, "Invariant");
221 return _phase_time_ms[phase];
222 }
223
224 void ReferenceProcessorPhaseTimes::set_phase_time_ms(RefProcPhases phase, double phase_time_ms) {
225 assert(phase >= RefPhase1 && phase < RefPhaseMax, "Invariant");
226 _phase_time_ms[phase] = phase_time_ms;
227 }
228
229 void ReferenceProcessorPhaseTimes::reset() {
230 for (int i = 0; i < RefPhaseMax; i++) {
231 _worker_time_sec[i]->reset();
232 _phase_time_ms[i] = uninitialized();
233 }
234
235 _balance_queues_time_ms = uninitialized();
236
237 _processing_is_mt = false;
238 }
239