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