< prev index next >

src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp

Print this page
rev 49680 : imported patch 6672778-partial-queue-trimming
rev 49681 : imported patch 6672778-refactoring
rev 49682 : [mq]: 6672778-stefanj-review
   1 /*
   2  * Copyright (c) 2013, 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/g1/g1CollectedHeap.inline.hpp"
  27 #include "gc/g1/g1GCPhaseTimes.hpp"
  28 #include "gc/g1/g1HotCardCache.hpp"

  29 #include "gc/g1/g1StringDedup.hpp"
  30 #include "gc/shared/workerDataArray.inline.hpp"
  31 #include "memory/resourceArea.hpp"
  32 #include "logging/log.hpp"
  33 #include "logging/logStream.hpp"
  34 #include "runtime/timer.hpp"
  35 #include "runtime/os.hpp"
  36 #include "utilities/macros.hpp"
  37 
  38 static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
  39 
  40 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
  41   _max_gc_threads(max_gc_threads),
  42   _gc_start_counter(0),
  43   _gc_pause_time_ms(0.0),
  44   _ref_phase_times((GCTimer*)gc_timer, max_gc_threads)
  45 {
  46   assert(max_gc_threads > 0, "Must have some GC threads");
  47 
  48   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");


 149   _cur_fast_reclaim_humongous_candidates = 0;
 150   _cur_fast_reclaim_humongous_reclaimed = 0;
 151   _cur_verify_before_time_ms = 0.0;
 152   _cur_verify_after_time_ms = 0.0;
 153 
 154   for (int i = 0; i < GCParPhasesSentinel; i++) {
 155     if (_gc_par_phases[i] != NULL) {
 156       _gc_par_phases[i]->reset();
 157     }
 158   }
 159 
 160   _ref_phase_times.reset();
 161 }
 162 
 163 void G1GCPhaseTimes::note_gc_start() {
 164   _gc_start_counter = os::elapsed_counter();
 165   reset();
 166 }
 167 
 168 #define ASSERT_PHASE_UNINITIALIZED(phase) \
 169     assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 170 
 171 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {



 172   double value = _gc_par_phases[phase]->get(worker);
 173   if (value != WorkerDataArray<double>::uninitialized()) {
 174     return value;
 175   }
 176   return 0.0;
 177 }
 178 
 179 void G1GCPhaseTimes::note_gc_end() {
 180   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 181 
 182   double uninitialized = WorkerDataArray<double>::uninitialized();
 183 
 184   for (uint i = 0; i < _max_gc_threads; i++) {
 185     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 186     if (worker_start != uninitialized) {
 187       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 188       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 189       record_time_secs(GCWorkerTotal, i , total_worker_time);
 190 
 191       double worker_known_time =
 192           worker_time(ExtRootScan, i)
 193           + worker_time(SATBFiltering, i)

 194           + worker_time(UpdateRS, i)
 195           + worker_time(ScanRS, i)
 196           + worker_time(CodeRoots, i)
 197           + worker_time(ObjCopy, i)
 198           + worker_time(Termination, i);
 199 
 200       record_time_secs(Other, i, total_worker_time - worker_known_time);
 201     } else {
 202       // Make sure all slots are uninitialized since this thread did not seem to have been started
 203       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 204       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 205       ASSERT_PHASE_UNINITIALIZED(SATBFiltering);

 206       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
 207       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 208       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 209       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 210       ASSERT_PHASE_UNINITIALIZED(Termination);
 211     }
 212   }
 213 }
 214 
 215 #undef ASSERT_PHASE_UNINITIALIZED
 216 
 217 // record the time a phase took in seconds
 218 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 219   _gc_par_phases[phase]->set(worker_i, secs);
 220 }
 221 
 222 // add a number of seconds to a phase
 223 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 224   _gc_par_phases[phase]->add(worker_i, secs);
 225 }
 226 








 227 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 228   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 229 }
 230 
 231 // return the average time for a phase in milliseconds
 232 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 233   return _gc_par_phases[phase]->average() * 1000.0;
 234 }
 235 
 236 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 237   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 238   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 239 }
 240 
 241 template <class T>
 242 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 243   LogTarget(Trace, gc, phases, task) lt;
 244   if (lt.is_enabled()) {
 245     LogStream ls(lt);
 246     ls.print("%s", indent);


 442 }
 443 
 444 void G1GCPhaseTimes::print() {
 445   note_gc_end();
 446 
 447   if (_cur_verify_before_time_ms > 0.0) {
 448     debug_time("Verify Before", _cur_verify_before_time_ms);
 449   }
 450 
 451   double accounted_ms = 0.0;
 452   accounted_ms += print_pre_evacuate_collection_set();
 453   accounted_ms += print_evacuate_collection_set();
 454   accounted_ms += print_post_evacuate_collection_set();
 455   print_other(accounted_ms);
 456 
 457   if (_cur_verify_after_time_ms > 0.0) {
 458     debug_time("Verify After", _cur_verify_after_time_ms);
 459   }
 460 }
 461 















 462 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
 463     _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
 464   if (_phase_times != NULL) {
 465     _start_time = os::elapsedTime();
 466   }
 467 }
 468 
 469 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 470   if (_phase_times != NULL) {
 471     _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);

















 472   }
 473 }
 474 
   1 /*
   2  * Copyright (c) 2013, 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/g1/g1CollectedHeap.inline.hpp"
  27 #include "gc/g1/g1GCPhaseTimes.hpp"
  28 #include "gc/g1/g1HotCardCache.hpp"
  29 #include "gc/g1/g1ParScanThreadState.inline.hpp"
  30 #include "gc/g1/g1StringDedup.hpp"
  31 #include "gc/shared/workerDataArray.inline.hpp"
  32 #include "memory/resourceArea.hpp"
  33 #include "logging/log.hpp"
  34 #include "logging/logStream.hpp"
  35 #include "runtime/timer.hpp"
  36 #include "runtime/os.hpp"
  37 #include "utilities/macros.hpp"
  38 
  39 static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
  40 
  41 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
  42   _max_gc_threads(max_gc_threads),
  43   _gc_start_counter(0),
  44   _gc_pause_time_ms(0.0),
  45   _ref_phase_times((GCTimer*)gc_timer, max_gc_threads)
  46 {
  47   assert(max_gc_threads > 0, "Must have some GC threads");
  48 
  49   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");


 150   _cur_fast_reclaim_humongous_candidates = 0;
 151   _cur_fast_reclaim_humongous_reclaimed = 0;
 152   _cur_verify_before_time_ms = 0.0;
 153   _cur_verify_after_time_ms = 0.0;
 154 
 155   for (int i = 0; i < GCParPhasesSentinel; i++) {
 156     if (_gc_par_phases[i] != NULL) {
 157       _gc_par_phases[i]->reset();
 158     }
 159   }
 160 
 161   _ref_phase_times.reset();
 162 }
 163 
 164 void G1GCPhaseTimes::note_gc_start() {
 165   _gc_start_counter = os::elapsed_counter();
 166   reset();
 167 }
 168 
 169 #define ASSERT_PHASE_UNINITIALIZED(phase) \
 170     assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 171 
 172 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
 173   if (_gc_par_phases[phase] == NULL) {
 174     return 0.0;
 175   }
 176   double value = _gc_par_phases[phase]->get(worker);
 177   if (value != WorkerDataArray<double>::uninitialized()) {
 178     return value;
 179   }
 180   return 0.0;
 181 }
 182 
 183 void G1GCPhaseTimes::note_gc_end() {
 184   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 185 
 186   double uninitialized = WorkerDataArray<double>::uninitialized();
 187 
 188   for (uint i = 0; i < _max_gc_threads; i++) {
 189     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 190     if (worker_start != uninitialized) {
 191       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 192       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 193       record_time_secs(GCWorkerTotal, i , total_worker_time);
 194 
 195       double worker_known_time =
 196           worker_time(ExtRootScan, i)
 197           + worker_time(SATBFiltering, i)
 198           + worker_time(ScanHCC, i)
 199           + worker_time(UpdateRS, i)
 200           + worker_time(ScanRS, i)
 201           + worker_time(CodeRoots, i)
 202           + worker_time(ObjCopy, i)
 203           + worker_time(Termination, i);
 204 
 205       record_time_secs(Other, i, total_worker_time - worker_known_time);
 206     } else {
 207       // Make sure all slots are uninitialized since this thread did not seem to have been started
 208       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 209       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 210       ASSERT_PHASE_UNINITIALIZED(SATBFiltering);
 211       ASSERT_PHASE_UNINITIALIZED(ScanHCC);
 212       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
 213       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 214       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 215       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 216       ASSERT_PHASE_UNINITIALIZED(Termination);
 217     }
 218   }
 219 }
 220 
 221 #undef ASSERT_PHASE_UNINITIALIZED
 222 
 223 // record the time a phase took in seconds
 224 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 225   _gc_par_phases[phase]->set(worker_i, secs);
 226 }
 227 
 228 // add a number of seconds to a phase
 229 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 230   _gc_par_phases[phase]->add(worker_i, secs);
 231 }
 232 
 233 void G1GCPhaseTimes::record_or_add_objcopy_time_secs(uint worker_i, double secs) {
 234   if (_gc_par_phases[ObjCopy]->get(worker_i) == _gc_par_phases[ObjCopy]->uninitialized()) {
 235     record_time_secs(ObjCopy, worker_i, secs);
 236   } else {
 237     add_time_secs(ObjCopy, worker_i, secs);
 238   }
 239 }
 240 
 241 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 242   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 243 }
 244 
 245 // return the average time for a phase in milliseconds
 246 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 247   return _gc_par_phases[phase]->average() * 1000.0;
 248 }
 249 
 250 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 251   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 252   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 253 }
 254 
 255 template <class T>
 256 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 257   LogTarget(Trace, gc, phases, task) lt;
 258   if (lt.is_enabled()) {
 259     LogStream ls(lt);
 260     ls.print("%s", indent);


 456 }
 457 
 458 void G1GCPhaseTimes::print() {
 459   note_gc_end();
 460 
 461   if (_cur_verify_before_time_ms > 0.0) {
 462     debug_time("Verify Before", _cur_verify_before_time_ms);
 463   }
 464 
 465   double accounted_ms = 0.0;
 466   accounted_ms += print_pre_evacuate_collection_set();
 467   accounted_ms += print_evacuate_collection_set();
 468   accounted_ms += print_post_evacuate_collection_set();
 469   print_other(accounted_ms);
 470 
 471   if (_cur_verify_after_time_ms > 0.0) {
 472     debug_time("Verify After", _cur_verify_after_time_ms);
 473   }
 474 }
 475 
 476 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
 477   _pss(pss),
 478   _start(Ticks::now()),
 479   _total_time(total_time),
 480   _trim_time(trim_time) {
 481 
 482   assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use");
 483 }
 484 
 485 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
 486   _total_time += (Ticks::now() - _start) + _pss->trim_ticks();
 487   _trim_time += _pss->trim_ticks();
 488   _pss->reset_trim_ticks();
 489 }
 490 
 491 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
 492     _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
 493   if (_phase_times != NULL) {
 494     _start_time = os::elapsedTime();
 495   }
 496 }
 497 
 498 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 499   if (_phase_times != NULL) {
 500     _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
 501   }
 502 }
 503 
 504 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
 505                                                  G1ParScanThreadState* pss,
 506                                                  G1GCPhaseTimes::GCParPhases phase,
 507                                                  uint worker_id) :
 508   G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
 509   _total_time(),
 510   _trim_time(),
 511   _trim_tracker(pss, _total_time, _trim_time) {
 512 }
 513 
 514 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
 515   if (_phase_times != NULL) {
 516     _start_time += TicksToTimeHelper::seconds(_trim_time);
 517     _phase_times->record_or_add_objcopy_time_secs(_worker_id, TicksToTimeHelper::seconds(_trim_time));
 518   }
 519 }
 520 
< prev index next >