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