rev 57242 : imported patch 8235341-workerdataarray-cleanup
rev 57243 : [mq]: 8235341-stefanj-review

   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>("GC Worker Start (ms):", max_gc_threads);
  52   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>("Ext Root Scanning (ms):", max_gc_threads);
  53 
  54   // Root scanning phases
  55   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>("Thread Roots (ms):", max_gc_threads);
  56   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>("Universe Roots (ms):", max_gc_threads);
  57   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>("JNI Handles Roots (ms):", max_gc_threads);
  58   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>("ObjectSynchronizer Roots (ms):", max_gc_threads);
  59   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>("Management Roots (ms):", max_gc_threads);
  60   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>("SystemDictionary Roots (ms):", max_gc_threads);
  61   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>("CLDG Roots (ms):", max_gc_threads);
  62   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>("JVMTI Roots (ms):", max_gc_threads);
  63   AOT_ONLY(_gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>("AOT Root Scan (ms):", max_gc_threads);)
  64   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>("CM RefProcessor Roots (ms):", max_gc_threads);
  65 
  66   _gc_par_phases[MergeER] = new WorkerDataArray<double>("Eager Reclaim (ms):", max_gc_threads);
  67 
  68   _gc_par_phases[MergeRS] = new WorkerDataArray<double>("Remembered Sets (ms):", max_gc_threads);
  69   _gc_par_phases[MergeRS]->create_thread_work_items("Merged Sparse:", MergeRSMergedSparse);
  70   _gc_par_phases[MergeRS]->create_thread_work_items("Merged Fine:", MergeRSMergedFine);
  71   _gc_par_phases[MergeRS]->create_thread_work_items("Merged Coarse:", MergeRSMergedCoarse);
  72   _gc_par_phases[MergeRS]->create_thread_work_items("Dirty Cards:", MergeRSDirtyCards);
  73 
  74   _gc_par_phases[OptMergeRS] = new WorkerDataArray<double>("Optional Remembered Sets (ms):", max_gc_threads);
  75   _gc_par_phases[OptMergeRS]->create_thread_work_items("Merged Sparse:", MergeRSMergedSparse);
  76   _gc_par_phases[OptMergeRS]->create_thread_work_items("Merged Fine:", MergeRSMergedFine);
  77   _gc_par_phases[OptMergeRS]->create_thread_work_items("Merged Coarse:", MergeRSMergedCoarse);
  78   _gc_par_phases[OptMergeRS]->create_thread_work_items("Dirty Cards:", MergeRSDirtyCards);








  79 
  80   _gc_par_phases[MergeLB] = new WorkerDataArray<double>("Log Buffers (ms):", max_gc_threads);
  81   if (G1HotCardCache::default_use_cache()) {
  82     _gc_par_phases[MergeHCC] = new WorkerDataArray<double>("Hot Card Cache (ms):", max_gc_threads);
  83     _gc_par_phases[MergeHCC]->create_thread_work_items("Dirty Cards:", MergeHCCDirtyCards);
  84     _gc_par_phases[MergeHCC]->create_thread_work_items("Skipped Cards:", MergeHCCSkippedCards);


  85   } else {
  86     _gc_par_phases[MergeHCC] = NULL;


  87   }
  88   _gc_par_phases[ScanHR] = new WorkerDataArray<double>("Scan Heap Roots (ms):", max_gc_threads);
  89   _gc_par_phases[OptScanHR] = new WorkerDataArray<double>("Optional Scan Heap Roots (ms):", max_gc_threads);
  90   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>("Code Root Scan (ms):", max_gc_threads);
  91   _gc_par_phases[OptCodeRoots] = new WorkerDataArray<double>("Optional Code Root Scan (ms):", max_gc_threads);
  92   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>("Object Copy (ms):", max_gc_threads);
  93   _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>("Optional Object Copy (ms):", max_gc_threads);
  94   _gc_par_phases[Termination] = new WorkerDataArray<double>("Termination (ms):", max_gc_threads);
  95   _gc_par_phases[OptTermination] = new WorkerDataArray<double>("Optional Termination (ms):", max_gc_threads);
  96   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>("GC Worker Total (ms):", max_gc_threads);
  97   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>("GC Worker End (ms):", max_gc_threads);
  98   _gc_par_phases[Other] = new WorkerDataArray<double>("GC Worker Other (ms):", max_gc_threads);
  99 
 100   _gc_par_phases[ScanHR]->create_thread_work_items("Scanned Cards:", ScanHRScannedCards);
 101   _gc_par_phases[ScanHR]->create_thread_work_items("Scanned Blocks:", ScanHRScannedBlocks);
 102   _gc_par_phases[ScanHR]->create_thread_work_items("Claimed Chunks:", ScanHRClaimedChunks);
 103 
 104   _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Cards:", ScanHRScannedCards);
 105   _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Blocks:", ScanHRScannedBlocks);
 106   _gc_par_phases[OptScanHR]->create_thread_work_items("Claimed Chunks:", ScanHRClaimedChunks);
 107   _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Refs:", ScanHRScannedOptRefs);
 108   _gc_par_phases[OptScanHR]->create_thread_work_items("Used Memory:", ScanHRUsedMemory);
 109 
 110   _gc_par_phases[MergeLB]->create_thread_work_items("Dirty Cards:", MergeLBDirtyCards);
 111   _gc_par_phases[MergeLB]->create_thread_work_items("Skipped Cards:", MergeLBSkippedCards);
 112 
 113   _gc_par_phases[MergePSS] = new WorkerDataArray<double>("Merge Per-Thread State", 1 /* length */, true /* is_serial */);
 114 
 115   _gc_par_phases[MergePSS]->create_thread_work_items("Copied Bytes", MergePSSCopiedBytes, max_gc_threads);
 116   _gc_par_phases[MergePSS]->create_thread_work_items("LAB Waste", MergePSSLABWasteBytes, max_gc_threads);
 117   _gc_par_phases[MergePSS]->create_thread_work_items("LAB Undo Waste", MergePSSLABUndoWasteBytes, max_gc_threads);













 118 
 119   _gc_par_phases[Termination]->create_thread_work_items("Termination Attempts:");

 120 
 121   _gc_par_phases[OptTermination]->create_thread_work_items("Optional Termination Attempts:");

 122 
 123   if (UseStringDeduplication) {
 124     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>("Queue Fixup (ms):", max_gc_threads);
 125     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>("Table Fixup (ms):", max_gc_threads);
 126   } else {
 127     _gc_par_phases[StringDedupQueueFixup] = NULL;
 128     _gc_par_phases[StringDedupTableFixup] = NULL;
 129   }
 130 
 131   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>("Parallel Redirty (ms):", max_gc_threads);
 132   _gc_par_phases[RedirtyCards]->create_thread_work_items("Redirtied Cards:");

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