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