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