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