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