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