< prev index next >

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

Print this page
rev 49826 : imported patch 6672778-partial-queue-trimming
rev 49827 : imported patch 6672778-refactoring
rev 49828 : imported patch 6672778-stefanj-review
rev 49829 : imported patch 6672778-inconsistent-time-fixes
rev 49830 : [mq]: 6672778-satb-timing-fix
   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):");


 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]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 171 
 172 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {



 173   double value = _gc_par_phases[phase]->get(worker);
 174   if (value != WorkerDataArray<double>::uninitialized()) {
 175     return value;
 176   }
 177   return 0.0;
 178 }
 179 
 180 void G1GCPhaseTimes::note_gc_end() {
 181   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 182 
 183   double uninitialized = WorkerDataArray<double>::uninitialized();
 184 
 185   for (uint i = 0; i < _max_gc_threads; i++) {
 186     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 187     if (worker_start != uninitialized) {
 188       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 189       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 190       record_time_secs(GCWorkerTotal, i , total_worker_time);
 191 
 192       double worker_known_time =
 193           worker_time(ExtRootScan, i)
 194           + worker_time(SATBFiltering, i)
 195           + worker_time(UpdateRS, i)
 196           + worker_time(ScanRS, i)
 197           + worker_time(CodeRoots, i)
 198           + worker_time(ObjCopy, i)
 199           + worker_time(Termination, i);
 200 
 201       record_time_secs(Other, i, total_worker_time - worker_known_time);
 202     } else {
 203       // Make sure all slots are uninitialized since this thread did not seem to have been started
 204       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 205       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 206       ASSERT_PHASE_UNINITIALIZED(SATBFiltering);
 207       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
 208       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 209       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 210       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 211       ASSERT_PHASE_UNINITIALIZED(Termination);
 212     }
 213   }
 214 }
 215 
 216 #undef ASSERT_PHASE_UNINITIALIZED
 217 
 218 // record the time a phase took in seconds
 219 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 220   _gc_par_phases[phase]->set(worker_i, secs);
 221 }
 222 
 223 // add a number of seconds to a phase
 224 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 225   _gc_par_phases[phase]->add(worker_i, secs);
 226 }
 227 








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


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















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


















 476   }
 477 }
 478 
   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):");


 151   _cur_fast_reclaim_humongous_candidates = 0;
 152   _cur_fast_reclaim_humongous_reclaimed = 0;
 153   _cur_verify_before_time_ms = 0.0;
 154   _cur_verify_after_time_ms = 0.0;
 155 
 156   for (int i = 0; i < GCParPhasesSentinel; i++) {
 157     if (_gc_par_phases[i] != NULL) {
 158       _gc_par_phases[i]->reset();
 159     }
 160   }
 161 
 162   _ref_phase_times.reset();
 163 }
 164 
 165 void G1GCPhaseTimes::note_gc_start() {
 166   _gc_start_counter = os::elapsed_counter();
 167   reset();
 168 }
 169 
 170 #define ASSERT_PHASE_UNINITIALIZED(phase) \
 171     assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 172 
 173 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
 174   if (_gc_par_phases[phase] == NULL) {
 175     return 0.0;
 176   }
 177   double value = _gc_par_phases[phase]->get(worker);
 178   if (value != WorkerDataArray<double>::uninitialized()) {
 179     return value;
 180   }
 181   return 0.0;
 182 }
 183 
 184 void G1GCPhaseTimes::note_gc_end() {
 185   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 186 
 187   double uninitialized = WorkerDataArray<double>::uninitialized();
 188 
 189   for (uint i = 0; i < _max_gc_threads; i++) {
 190     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 191     if (worker_start != uninitialized) {
 192       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 193       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 194       record_time_secs(GCWorkerTotal, i , total_worker_time);
 195 
 196       double worker_known_time = worker_time(ExtRootScan, i) +
 197                                  worker_time(ScanHCC, i) +
 198                                  worker_time(UpdateRS, i) +
 199                                  worker_time(ScanRS, i) +
 200                                  worker_time(CodeRoots, i) +
 201                                  worker_time(ObjCopy, i) +
 202                                  worker_time(Termination, i);

 203 
 204       record_time_secs(Other, i, total_worker_time - worker_known_time);
 205     } else {
 206       // Make sure all slots are uninitialized since this thread did not seem to have been started
 207       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 208       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 209       ASSERT_PHASE_UNINITIALIZED(ScanHCC);
 210       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
 211       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 212       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 213       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 214       ASSERT_PHASE_UNINITIALIZED(Termination);
 215     }
 216   }
 217 }
 218 
 219 #undef ASSERT_PHASE_UNINITIALIZED
 220 
 221 // record the time a phase took in seconds
 222 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 223   _gc_par_phases[phase]->set(worker_i, secs);
 224 }
 225 
 226 // add a number of seconds to a phase
 227 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 228   _gc_par_phases[phase]->add(worker_i, secs);
 229 }
 230 
 231 void G1GCPhaseTimes::record_or_add_objcopy_time_secs(uint worker_i, double secs) {
 232   if (_gc_par_phases[ObjCopy]->get(worker_i) == _gc_par_phases[ObjCopy]->uninitialized()) {
 233     record_time_secs(ObjCopy, worker_i, secs);
 234   } else {
 235     add_time_secs(ObjCopy, worker_i, secs);
 236   }
 237 }
 238 
 239 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 240   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 241 }
 242 
 243 // return the average time for a phase in milliseconds
 244 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 245   return _gc_par_phases[phase]->average() * 1000.0;
 246 }
 247 
 248 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 249   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 250   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 251 }
 252 
 253 template <class T>
 254 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 255   LogTarget(Trace, gc, phases, task) lt;
 256   if (lt.is_enabled()) {
 257     LogStream ls(lt);
 258     ls.print("%s", indent);


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