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/gcTimer.hpp"
  32 #include "gc/shared/workerDataArray.inline.hpp"
  33 #include "memory/resourceArea.hpp"
  34 #include "logging/log.hpp"
  35 #include "logging/logStream.hpp"
  36 #include "runtime/timer.hpp"
  37 #include "runtime/os.hpp"
  38 #include "utilities/macros.hpp"
  39 
  40 static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
  41 
  42 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
  43   _max_gc_threads(max_gc_threads),
  44   _gc_start_counter(0),
  45   _gc_pause_time_ms(0.0),
  46   _ref_phase_times(gc_timer, max_gc_threads),
  47   _weak_phase_times(max_gc_threads)
  48 {
  49   assert(max_gc_threads > 0, "Must have some GC threads");
  50 
  51   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
  52   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
  53 
  54   // Root scanning phases
  55   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
  56   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
  57   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  58   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  59   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  60   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  61   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  62   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  63   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  64   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  65   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
  66   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
  67   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
  68 
  69   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
  70   if (G1HotCardCache::default_use_cache()) {
  71     _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
  72   } else {
  73     _gc_par_phases[ScanHCC] = NULL;
  74   }
  75   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");
  76   _gc_par_phases[OptScanRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan RS (ms):");
  77   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");
  78 #if INCLUDE_AOT
  79   _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scanning (ms):");
  80 #endif
  81   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
  82   _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):");
  83   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
  84   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
  85   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
  86   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
  87 
  88   _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  89   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
  90   _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  91   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
  92   _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  93   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
  94 
  95   _opt_cset_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  96   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_scanned_cards, OptCSetScannedCards);
  97   _opt_cset_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  98   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_claimed_cards, OptCSetClaimedCards);
  99   _opt_cset_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
 100   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_skipped_cards, OptCSetSkippedCards);
 101   _opt_cset_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:");
 102   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_used_memory, OptCSetUsedMemory);
 103 
 104   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
 105   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
 106   _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
 107   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
 108   _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
 109   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
 110 
 111   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
 112   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 113 
 114   if (UseStringDeduplication) {
 115     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
 116     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
 117   } else {
 118     _gc_par_phases[StringDedupQueueFixup] = NULL;
 119     _gc_par_phases[StringDedupTableFixup] = NULL;
 120   }
 121 
 122   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
 123   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
 124   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 125 
 126   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
 127   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
 128 
 129   reset();
 130 }
 131 
 132 void G1GCPhaseTimes::reset() {
 133   _cur_collection_par_time_ms = 0.0;
 134   _cur_optional_evac_ms = 0.0;
 135   _cur_collection_code_root_fixup_time_ms = 0.0;
 136   _cur_strong_code_root_purge_time_ms = 0.0;
 137   _cur_evac_fail_recalc_used = 0.0;
 138   _cur_evac_fail_remove_self_forwards = 0.0;
 139   _cur_string_dedup_fixup_time_ms = 0.0;
 140   _cur_prepare_tlab_time_ms = 0.0;
 141   _cur_resize_tlab_time_ms = 0.0;
 142   _cur_derived_pointer_table_update_time_ms = 0.0;
 143   _cur_clear_ct_time_ms = 0.0;
 144   _cur_expand_heap_time_ms = 0.0;
 145   _cur_ref_proc_time_ms = 0.0;
 146   _cur_collection_start_sec = 0.0;
 147   _root_region_scan_wait_time_ms = 0.0;
 148   _external_accounted_time_ms = 0.0;
 149   _recorded_clear_claimed_marks_time_ms = 0.0;
 150   _recorded_young_cset_choice_time_ms = 0.0;
 151   _recorded_non_young_cset_choice_time_ms = 0.0;
 152   _recorded_redirty_logged_cards_time_ms = 0.0;
 153   _recorded_preserve_cm_referents_time_ms = 0.0;
 154   _recorded_merge_pss_time_ms = 0.0;
 155   _recorded_start_new_cset_time_ms = 0.0;
 156   _recorded_total_free_cset_time_ms = 0.0;
 157   _recorded_serial_free_cset_time_ms = 0.0;
 158   _cur_fast_reclaim_humongous_time_ms = 0.0;
 159   _cur_fast_reclaim_humongous_register_time_ms = 0.0;
 160   _cur_fast_reclaim_humongous_total = 0;
 161   _cur_fast_reclaim_humongous_candidates = 0;
 162   _cur_fast_reclaim_humongous_reclaimed = 0;
 163   _cur_verify_before_time_ms = 0.0;
 164   _cur_verify_after_time_ms = 0.0;
 165 
 166   for (int i = 0; i < GCParPhasesSentinel; i++) {
 167     if (_gc_par_phases[i] != NULL) {
 168       _gc_par_phases[i]->reset();
 169     }
 170   }
 171 
 172   _ref_phase_times.reset();
 173   _weak_phase_times.reset();
 174 }
 175 
 176 void G1GCPhaseTimes::note_gc_start() {
 177   _gc_start_counter = os::elapsed_counter();
 178   reset();
 179 }
 180 
 181 #define ASSERT_PHASE_UNINITIALIZED(phase) \
 182     assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 183 
 184 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
 185   if (_gc_par_phases[phase] == NULL) {
 186     return 0.0;
 187   }
 188   double value = _gc_par_phases[phase]->get(worker);
 189   if (value != WorkerDataArray<double>::uninitialized()) {
 190     return value;
 191   }
 192   return 0.0;
 193 }
 194 
 195 void G1GCPhaseTimes::note_gc_end() {
 196   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 197 
 198   double uninitialized = WorkerDataArray<double>::uninitialized();
 199 
 200   for (uint i = 0; i < _max_gc_threads; i++) {
 201     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 202     if (worker_start != uninitialized) {
 203       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 204       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 205       record_time_secs(GCWorkerTotal, i , total_worker_time);
 206 
 207       double worker_known_time = worker_time(ExtRootScan, i) +
 208                                  worker_time(ScanHCC, i) +
 209                                  worker_time(UpdateRS, i) +
 210                                  worker_time(ScanRS, i) +
 211                                  worker_time(CodeRoots, i) +
 212                                  worker_time(ObjCopy, i) +
 213                                  worker_time(Termination, i);
 214 
 215       record_time_secs(Other, i, total_worker_time - worker_known_time);
 216     } else {
 217       // Make sure all slots are uninitialized since this thread did not seem to have been started
 218       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 219       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 220       ASSERT_PHASE_UNINITIALIZED(ScanHCC);
 221       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
 222       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 223       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 224       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 225       ASSERT_PHASE_UNINITIALIZED(Termination);
 226     }
 227   }
 228 }
 229 
 230 #undef ASSERT_PHASE_UNINITIALIZED
 231 
 232 // record the time a phase took in seconds
 233 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 234   _gc_par_phases[phase]->set(worker_i, secs);
 235 }
 236 
 237 // add a number of seconds to a phase
 238 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 239   _gc_par_phases[phase]->add(worker_i, secs);
 240 }
 241 
 242 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 243   if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) {
 244     record_time_secs(phase, worker_i, secs);
 245   } else {
 246     add_time_secs(phase, worker_i, secs);
 247   }
 248 }
 249 
 250 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 251   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 252 }
 253 
 254 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 255   _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index);
 256 }
 257 
 258 // return the average time for a phase in milliseconds
 259 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 260   return _gc_par_phases[phase]->average() * 1000.0;
 261 }
 262 
 263 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 264   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 265   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 266 }
 267 
 268 template <class T>
 269 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 270   LogTarget(Trace, gc, phases, task) lt;
 271   if (lt.is_enabled()) {
 272     LogStream ls(lt);
 273     ls.print("%s", indent);
 274     phase->print_details_on(&ls);
 275   }
 276 }
 277 
 278 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
 279   out->print("%s", Indents[indent]);
 280   phase->print_summary_on(out, print_sum);
 281   details(phase, Indents[indent]);
 282 
 283   for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
 284     WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
 285     if (work_items != NULL) {
 286       out->print("%s", Indents[indent + 1]);
 287       work_items->print_summary_on(out, true);
 288       details(work_items, Indents[indent + 1]);
 289     }
 290   }
 291 }
 292 
 293 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) const {
 294   LogTarget(Debug, gc, phases) lt;
 295   if (lt.is_enabled()) {
 296     ResourceMark rm;
 297     LogStream ls(lt);
 298     log_phase(phase, 2, &ls, true);
 299   }
 300 }
 301 
 302 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
 303   LogTarget(Trace, gc, phases) lt;
 304   if (lt.is_enabled()) {
 305     LogStream ls(lt);
 306     log_phase(phase, 3, &ls, print_sum);
 307   }
 308 }
 309 
 310 #define TIME_FORMAT "%.1lfms"
 311 
 312 void G1GCPhaseTimes::info_time(const char* name, double value) const {
 313   log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
 314 }
 315 
 316 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
 317   log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
 318 }
 319 
 320 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
 321   LogTarget(Debug, gc, phases) lt;
 322   LogTarget(Debug, gc, phases, ref) lt2;
 323 
 324   if (lt.is_enabled()) {
 325     LogStream ls(lt);
 326     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 327   } else if (lt2.is_enabled()) {
 328     LogStream ls(lt2);
 329     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 330   }
 331 }
 332 
 333 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
 334   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
 335 }
 336 
 337 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 338   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
 339 }
 340 
 341 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 342   const double sum_ms = _root_region_scan_wait_time_ms +
 343                         _recorded_young_cset_choice_time_ms +
 344                         _recorded_non_young_cset_choice_time_ms +
 345                         _cur_fast_reclaim_humongous_register_time_ms +
 346                         _recorded_clear_claimed_marks_time_ms;
 347 
 348   info_time("Pre Evacuate Collection Set", sum_ms);
 349 
 350   if (_root_region_scan_wait_time_ms > 0.0) {
 351     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 352   }
 353   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
 354   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
 355   if (G1EagerReclaimHumongousObjects) {
 356     debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 357     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
 358     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 359   }
 360 
 361   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
 362     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
 363   }
 364   return sum_ms;
 365 }
 366 
 367 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
 368   const double sum_ms = _cur_optional_evac_ms;
 369   if (sum_ms > 0) {
 370     info_time("Evacuate Optional Collection Set", sum_ms);
 371     debug_phase(_gc_par_phases[OptScanRS]);
 372     debug_phase(_gc_par_phases[OptObjCopy]);
 373   }
 374   return sum_ms;
 375 }
 376 
 377 double G1GCPhaseTimes::print_evacuate_collection_set() const {
 378   const double sum_ms = _cur_collection_par_time_ms;
 379 
 380   info_time("Evacuate Collection Set", sum_ms);
 381 
 382   trace_phase(_gc_par_phases[GCWorkerStart], false);
 383   debug_phase(_gc_par_phases[ExtRootScan]);
 384   for (int i = ThreadRoots; i <= SATBFiltering; i++) {
 385     trace_phase(_gc_par_phases[i]);
 386   }
 387   debug_phase(_gc_par_phases[UpdateRS]);
 388   if (G1HotCardCache::default_use_cache()) {
 389     trace_phase(_gc_par_phases[ScanHCC]);
 390   }
 391   debug_phase(_gc_par_phases[ScanRS]);
 392   debug_phase(_gc_par_phases[CodeRoots]);
 393 #if INCLUDE_AOT
 394   debug_phase(_gc_par_phases[AOTCodeRoots]);
 395 #endif
 396   debug_phase(_gc_par_phases[ObjCopy]);
 397   debug_phase(_gc_par_phases[Termination]);
 398   debug_phase(_gc_par_phases[Other]);
 399   debug_phase(_gc_par_phases[GCWorkerTotal]);
 400   trace_phase(_gc_par_phases[GCWorkerEnd], false);
 401 
 402   return sum_ms;
 403 }
 404 
 405 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
 406   const double evac_fail_handling = _cur_evac_fail_recalc_used +
 407                                     _cur_evac_fail_remove_self_forwards;
 408   const double sum_ms = evac_fail_handling +
 409                         _cur_collection_code_root_fixup_time_ms +
 410                         _recorded_preserve_cm_referents_time_ms +
 411                         _cur_ref_proc_time_ms +
 412                         (_weak_phase_times.total_time_sec() * MILLIUNITS) +
 413                         _cur_clear_ct_time_ms +
 414                         _recorded_merge_pss_time_ms +
 415                         _cur_strong_code_root_purge_time_ms +
 416                         _recorded_redirty_logged_cards_time_ms +
 417                         _recorded_total_free_cset_time_ms +
 418                         _cur_fast_reclaim_humongous_time_ms +
 419                         _cur_expand_heap_time_ms +
 420                         _cur_string_dedup_fixup_time_ms;
 421 
 422   info_time("Post Evacuate Collection Set", sum_ms);
 423 
 424   debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
 425 
 426   debug_time("Clear Card Table", _cur_clear_ct_time_ms);
 427 
 428   debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
 429   _ref_phase_times.print_all_references(2, false);
 430   _weak_phase_times.log_print(2);
 431 
 432   if (G1StringDedup::is_enabled()) {
 433     debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
 434     debug_phase(_gc_par_phases[StringDedupQueueFixup]);
 435     debug_phase(_gc_par_phases[StringDedupTableFixup]);
 436   }
 437 
 438   if (G1CollectedHeap::heap()->evacuation_failed()) {
 439     debug_time("Evacuation Failure", evac_fail_handling);
 440     trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
 441     trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
 442   }
 443 
 444   debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
 445   debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
 446 
 447   debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 448   trace_phase(_gc_par_phases[RedirtyCards]);
 449 #if COMPILER2_OR_JVMCI
 450   debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
 451 #endif
 452 
 453   debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
 454   trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
 455   trace_phase(_gc_par_phases[YoungFreeCSet]);
 456   trace_phase(_gc_par_phases[NonYoungFreeCSet]);
 457 
 458   if (G1EagerReclaimHumongousObjects) {
 459     debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 460     trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
 461   }
 462   debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
 463   if (UseTLAB && ResizeTLAB) {
 464     debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
 465   }
 466   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
 467 
 468 
 469   return sum_ms;
 470 }
 471 
 472 void G1GCPhaseTimes::print_other(double accounted_ms) const {
 473   info_time("Other", _gc_pause_time_ms - accounted_ms);
 474 }
 475 
 476 void G1GCPhaseTimes::print() {
 477   note_gc_end();
 478 
 479   if (_cur_verify_before_time_ms > 0.0) {
 480     debug_time("Verify Before", _cur_verify_before_time_ms);
 481   }
 482 
 483   double accounted_ms = 0.0;
 484   accounted_ms += print_pre_evacuate_collection_set();
 485   accounted_ms += print_evacuate_collection_set();
 486   accounted_ms += print_evacuate_optional_collection_set();
 487   accounted_ms += print_post_evacuate_collection_set();
 488   print_other(accounted_ms);
 489 
 490   if (_cur_verify_after_time_ms > 0.0) {
 491     debug_time("Verify After", _cur_verify_after_time_ms);
 492   }
 493 }
 494 
 495 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
 496   static const char* names[] = {
 497       "GCWorkerStart",
 498       "ExtRootScan",
 499       "ThreadRoots",
 500       "StringTableRoots",
 501       "UniverseRoots",
 502       "JNIRoots",
 503       "ObjectSynchronizerRoots",
 504       "ManagementRoots",
 505       "SystemDictionaryRoots",
 506       "CLDGRoots",
 507       "JVMTIRoots",
 508       "CMRefRoots",
 509       "WaitForStrongCLD",
 510       "WeakCLDRoots",
 511       "SATBFiltering",
 512       "UpdateRS",
 513       "ScanHCC",
 514       "ScanRS",
 515       "OptScanRS",
 516       "CodeRoots",
 517 #if INCLUDE_AOT
 518       "AOTCodeRoots",
 519 #endif
 520       "ObjCopy",
 521       "OptObjCopy",
 522       "Termination",
 523       "Other",
 524       "GCWorkerTotal",
 525       "GCWorkerEnd",
 526       "StringDedupQueueFixup",
 527       "StringDedupTableFixup",
 528       "RedirtyCards",
 529       "YoungFreeCSet",
 530       "NonYoungFreeCSet"
 531       //GCParPhasesSentinel only used to tell end of enum
 532       };
 533 
 534   STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
 535 
 536   return names[phase];
 537 }
 538 
 539 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
 540   _pss(pss),
 541   _start(Ticks::now()),
 542   _total_time(total_time),
 543   _trim_time(trim_time),
 544   _stopped(false) {
 545 
 546   assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use");
 547 }
 548 
 549 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
 550   if (!_stopped) {
 551     stop();
 552   }
 553 }
 554 
 555 void G1EvacPhaseWithTrimTimeTracker::stop() {
 556   assert(!_stopped, "Should only be called once");
 557   _total_time += (Ticks::now() - _start) - _pss->trim_ticks();
 558   _trim_time += _pss->trim_ticks();
 559   _pss->reset_trim_ticks();
 560   _stopped = true;
 561 }
 562 
 563 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
 564   _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event() {
 565   if (_phase_times != NULL) {
 566     _start_time = Ticks::now();
 567   }
 568 }
 569 
 570 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 571   if (_phase_times != NULL) {
 572     _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
 573     _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
 574   }
 575 }
 576 
 577 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
 578                                                  G1ParScanThreadState* pss,
 579                                                  G1GCPhaseTimes::GCParPhases phase,
 580                                                  uint worker_id) :
 581   G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
 582   _total_time(),
 583   _trim_time(),
 584   _trim_tracker(pss, _total_time, _trim_time) {
 585 }
 586 
 587 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
 588   if (_phase_times != NULL) {
 589     // Explicitly stop the trim tracker since it's not yet destructed.
 590     _trim_tracker.stop();
 591     // Exclude trim time by increasing the start time.
 592     _start_time += _trim_time;
 593     _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds());
 594   }
 595 }
 596