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   _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
 111   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
 112   _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
 113   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
 114 
 115   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
 116   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 117 
 118   if (UseStringDeduplication) {
 119     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
 120     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
 121   } else {
 122     _gc_par_phases[StringDedupQueueFixup] = NULL;
 123     _gc_par_phases[StringDedupTableFixup] = NULL;
 124   }
 125 
 126   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
 127   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
 128   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 129 
 130   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
 131   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
 132 
 133   reset();
 134 }
 135 
 136 void G1GCPhaseTimes::reset() {
 137   _cur_collection_par_time_ms = 0.0;
 138   _cur_optional_evac_ms = 0.0;
 139   _cur_collection_code_root_fixup_time_ms = 0.0;
 140   _cur_strong_code_root_purge_time_ms = 0.0;
 141   _cur_evac_fail_recalc_used = 0.0;
 142   _cur_evac_fail_remove_self_forwards = 0.0;
 143   _cur_string_deduplication_time_ms = 0.0;
 144   _cur_prepare_tlab_time_ms = 0.0;
 145   _cur_resize_tlab_time_ms = 0.0;
 146   _cur_derived_pointer_table_update_time_ms = 0.0;
 147   _cur_clear_ct_time_ms = 0.0;
 148   _cur_expand_heap_time_ms = 0.0;
 149   _cur_ref_proc_time_ms = 0.0;
 150   _cur_collection_start_sec = 0.0;
 151   _root_region_scan_wait_time_ms = 0.0;
 152   _external_accounted_time_ms = 0.0;
 153   _recorded_clear_claimed_marks_time_ms = 0.0;
 154   _recorded_young_cset_choice_time_ms = 0.0;
 155   _recorded_non_young_cset_choice_time_ms = 0.0;
 156   _recorded_redirty_logged_cards_time_ms = 0.0;
 157   _recorded_preserve_cm_referents_time_ms = 0.0;
 158   _recorded_merge_pss_time_ms = 0.0;
 159   _recorded_start_new_cset_time_ms = 0.0;
 160   _recorded_total_free_cset_time_ms = 0.0;
 161   _recorded_serial_free_cset_time_ms = 0.0;
 162   _cur_fast_reclaim_humongous_time_ms = 0.0;
 163   _cur_fast_reclaim_humongous_register_time_ms = 0.0;
 164   _cur_fast_reclaim_humongous_total = 0;
 165   _cur_fast_reclaim_humongous_candidates = 0;
 166   _cur_fast_reclaim_humongous_reclaimed = 0;
 167   _cur_verify_before_time_ms = 0.0;
 168   _cur_verify_after_time_ms = 0.0;
 169 
 170   for (int i = 0; i < GCParPhasesSentinel; i++) {
 171     if (_gc_par_phases[i] != NULL) {
 172       _gc_par_phases[i]->reset();
 173     }
 174   }
 175 
 176   _ref_phase_times.reset();
 177   _weak_phase_times.reset();
 178 }
 179 
 180 void G1GCPhaseTimes::note_gc_start() {
 181   _gc_start_counter = os::elapsed_counter();
 182   reset();
 183 }
 184 
 185 #define ASSERT_PHASE_UNINITIALIZED(phase) \
 186     assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 187 
 188 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
 189   if (_gc_par_phases[phase] == NULL) {
 190     return 0.0;
 191   }
 192   double value = _gc_par_phases[phase]->get(worker);
 193   if (value != WorkerDataArray<double>::uninitialized()) {
 194     return value;
 195   }
 196   return 0.0;
 197 }
 198 
 199 void G1GCPhaseTimes::note_gc_end() {
 200   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 201 
 202   double uninitialized = WorkerDataArray<double>::uninitialized();
 203 
 204   for (uint i = 0; i < _max_gc_threads; i++) {
 205     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 206     if (worker_start != uninitialized) {
 207       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 208       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 209       record_time_secs(GCWorkerTotal, i , total_worker_time);
 210 
 211       double worker_known_time = worker_time(ExtRootScan, i) +
 212                                  worker_time(ScanHCC, i) +
 213                                  worker_time(UpdateRS, i) +
 214                                  worker_time(ScanRS, i) +
 215                                  worker_time(CodeRoots, i) +
 216                                  worker_time(ObjCopy, i) +
 217                                  worker_time(Termination, i);
 218 
 219       record_time_secs(Other, i, total_worker_time - worker_known_time);
 220     } else {
 221       // Make sure all slots are uninitialized since this thread did not seem to have been started
 222       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 223       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 224       ASSERT_PHASE_UNINITIALIZED(ScanHCC);
 225       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
 226       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 227       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 228       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 229       ASSERT_PHASE_UNINITIALIZED(Termination);
 230     }
 231   }
 232 }
 233 
 234 #undef ASSERT_PHASE_UNINITIALIZED
 235 
 236 // record the time a phase took in seconds
 237 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 238   _gc_par_phases[phase]->set(worker_i, secs);
 239 }
 240 
 241 // add a number of seconds to a phase
 242 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 243   _gc_par_phases[phase]->add(worker_i, secs);
 244 }
 245 
 246 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 247   if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) {
 248     record_time_secs(phase, worker_i, secs);
 249   } else {
 250     add_time_secs(phase, worker_i, secs);
 251   }
 252 }
 253 
 254 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 255   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 256 }
 257 
 258 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 259   _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index);
 260 }
 261 
 262 // return the average time for a phase in milliseconds
 263 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 264   return _gc_par_phases[phase]->average() * 1000.0;
 265 }
 266 
 267 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 268   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 269   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 270 }
 271 
 272 template <class T>
 273 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 274   LogTarget(Trace, gc, phases, task) lt;
 275   if (lt.is_enabled()) {
 276     LogStream ls(lt);
 277     ls.print("%s", indent);
 278     phase->print_details_on(&ls);
 279   }
 280 }
 281 
 282 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) const {
 283   out->print("%s", Indents[indent]);
 284   phase->print_summary_on(out, print_sum);
 285   details(phase, Indents[indent]);
 286 
 287   for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
 288     WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
 289     if (work_items != NULL) {
 290       out->print("%s", Indents[indent + 1]);
 291       work_items->print_summary_on(out, true);
 292       details(work_items, Indents[indent + 1]);
 293     }
 294   }
 295 }
 296 
 297 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const {
 298   LogTarget(Debug, gc, phases) lt;
 299   if (lt.is_enabled()) {
 300     ResourceMark rm;
 301     LogStream ls(lt);
 302     log_phase(phase, 2 + extra_indent, &ls, true);
 303   }
 304 }
 305 
 306 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
 307   LogTarget(Trace, gc, phases) lt;
 308   if (lt.is_enabled()) {
 309     LogStream ls(lt);
 310     log_phase(phase, 3, &ls, print_sum);
 311   }
 312 }
 313 
 314 #define TIME_FORMAT "%.1lfms"
 315 
 316 void G1GCPhaseTimes::info_time(const char* name, double value) const {
 317   log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
 318 }
 319 
 320 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
 321   log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
 322 }
 323 
 324 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
 325   LogTarget(Debug, gc, phases) lt;
 326   LogTarget(Debug, gc, phases, ref) lt2;
 327 
 328   if (lt.is_enabled()) {
 329     LogStream ls(lt);
 330     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 331   } else if (lt2.is_enabled()) {
 332     LogStream ls(lt2);
 333     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 334   }
 335 }
 336 
 337 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
 338   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
 339 }
 340 
 341 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 342   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
 343 }
 344 
 345 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 346   const double sum_ms = _root_region_scan_wait_time_ms +
 347                         _recorded_young_cset_choice_time_ms +
 348                         _recorded_non_young_cset_choice_time_ms +
 349                         _cur_fast_reclaim_humongous_register_time_ms +
 350                         _recorded_clear_claimed_marks_time_ms;
 351 
 352   info_time("Pre Evacuate Collection Set", sum_ms);
 353 
 354   if (_root_region_scan_wait_time_ms > 0.0) {
 355     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 356   }
 357   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
 358   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
 359   if (G1EagerReclaimHumongousObjects) {
 360     debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 361     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
 362     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 363   }
 364 
 365   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
 366     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
 367   }
 368   return sum_ms;
 369 }
 370 
 371 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
 372   const double sum_ms = _cur_optional_evac_ms;
 373   if (sum_ms > 0) {
 374     info_time("Evacuate Optional Collection Set", sum_ms);
 375     debug_phase(_gc_par_phases[OptScanRS]);
 376     debug_phase(_gc_par_phases[OptObjCopy]);
 377   }
 378   return sum_ms;
 379 }
 380 
 381 double G1GCPhaseTimes::print_evacuate_collection_set() const {
 382   const double sum_ms = _cur_collection_par_time_ms;
 383 
 384   info_time("Evacuate Collection Set", sum_ms);
 385 
 386   trace_phase(_gc_par_phases[GCWorkerStart], false);
 387   debug_phase(_gc_par_phases[ExtRootScan]);
 388   for (int i = ExtRootScanSubPhasesStart; i <= ExtRootScanSubPhasesEnd; i++) {
 389     trace_phase(_gc_par_phases[i]);
 390   }
 391   if (G1HotCardCache::default_use_cache()) {
 392     debug_phase(_gc_par_phases[ScanHCC]);
 393   }
 394   debug_phase(_gc_par_phases[UpdateRS]);
 395   debug_phase(_gc_par_phases[ScanRS]);
 396   debug_phase(_gc_par_phases[CodeRoots]);
 397   debug_phase(_gc_par_phases[ObjCopy]);
 398   debug_phase(_gc_par_phases[Termination]);
 399   debug_phase(_gc_par_phases[Other]);
 400   debug_phase(_gc_par_phases[GCWorkerTotal]);
 401   trace_phase(_gc_par_phases[GCWorkerEnd], false);
 402 
 403   return sum_ms;
 404 }
 405 
 406 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
 407   const double evac_fail_handling = _cur_evac_fail_recalc_used +
 408                                     _cur_evac_fail_remove_self_forwards;
 409   const double sum_ms = evac_fail_handling +
 410                         _cur_collection_code_root_fixup_time_ms +
 411                         _recorded_preserve_cm_referents_time_ms +
 412                         _cur_ref_proc_time_ms +
 413                         (_weak_phase_times.total_time_sec() * MILLIUNITS) +
 414                         _cur_clear_ct_time_ms +
 415                         _recorded_merge_pss_time_ms +
 416                         _cur_strong_code_root_purge_time_ms +
 417                         _recorded_redirty_logged_cards_time_ms +
 418                         _recorded_total_free_cset_time_ms +
 419                         _cur_fast_reclaim_humongous_time_ms +
 420                         _cur_expand_heap_time_ms +
 421                         _cur_string_deduplication_time_ms;
 422 
 423   info_time("Post Evacuate Collection Set", sum_ms);
 424 
 425   debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
 426 
 427   debug_time("Clear Card Table", _cur_clear_ct_time_ms);
 428 
 429   debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
 430   _ref_phase_times.print_all_references(2, false);
 431   _weak_phase_times.log_print(2);
 432 
 433   if (G1StringDedup::is_enabled()) {
 434     debug_time("String Deduplication", _cur_string_deduplication_time_ms);
 435     debug_phase(_gc_par_phases[StringDedupQueueFixup], 1);
 436     debug_phase(_gc_par_phases[StringDedupTableFixup], 1);
 437   }
 438 
 439   if (G1CollectedHeap::heap()->evacuation_failed()) {
 440     debug_time("Evacuation Failure", evac_fail_handling);
 441     trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
 442     trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
 443   }
 444 
 445   debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
 446   debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
 447 
 448   debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 449   trace_phase(_gc_par_phases[RedirtyCards]);
 450 #if COMPILER2_OR_JVMCI
 451   debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
 452 #endif
 453 
 454   debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
 455   trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
 456   trace_phase(_gc_par_phases[YoungFreeCSet]);
 457   trace_phase(_gc_par_phases[NonYoungFreeCSet]);
 458 
 459   if (G1EagerReclaimHumongousObjects) {
 460     debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 461     trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
 462   }
 463   debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
 464   if (UseTLAB && ResizeTLAB) {
 465     debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
 466   }
 467   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
 468 
 469 
 470   return sum_ms;
 471 }
 472 
 473 void G1GCPhaseTimes::print_other(double accounted_ms) const {
 474   info_time("Other", _gc_pause_time_ms - accounted_ms);
 475 }
 476 
 477 void G1GCPhaseTimes::print() {
 478   note_gc_end();
 479 
 480   if (_cur_verify_before_time_ms > 0.0) {
 481     debug_time("Verify Before", _cur_verify_before_time_ms);
 482   }
 483 
 484   double accounted_ms = 0.0;
 485   accounted_ms += print_pre_evacuate_collection_set();
 486   accounted_ms += print_evacuate_collection_set();
 487   accounted_ms += print_evacuate_optional_collection_set();
 488   accounted_ms += print_post_evacuate_collection_set();
 489   print_other(accounted_ms);
 490 
 491   if (_cur_verify_after_time_ms > 0.0) {
 492     debug_time("Verify After", _cur_verify_after_time_ms);
 493   }
 494 }
 495 
 496 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
 497   static const char* names[] = {
 498       "GCWorkerStart",
 499       "ExtRootScan",
 500       "ThreadRoots",
 501       "UniverseRoots",
 502       "JNIRoots",
 503       "ObjectSynchronizerRoots",
 504       "ManagementRoots",
 505       "SystemDictionaryRoots",
 506       "CLDGRoots",
 507       "JVMTIRoots",
 508 #if INCLUDE_AOT
 509       "AOTCodeRoots",
 510 #endif
 511       "CMRefRoots",
 512       "WaitForStrongCLD",
 513       "WeakCLDRoots",
 514       "SATBFiltering",
 515       "UpdateRS",
 516       "ScanHCC",
 517       "ScanRS",
 518       "OptScanRS",
 519       "CodeRoots",
 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