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