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", "    ");
  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)("  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