< prev index next >

src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp

Print this page




  44   _gc_start_counter(0),
  45   _gc_pause_time_ms(0.0),
  46   _ref_phase_times(gc_timer, max_gc_threads),
  47   _weak_phase_times(max_gc_threads)
  48 {
  49   assert(max_gc_threads > 0, "Must have some GC threads");
  50 
  51   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
  52   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
  53 
  54   // Root scanning phases
  55   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
  56   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  57   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  58   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  59   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  60   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  61   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  62   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  63   AOT_ONLY(_gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scan (ms):");)

  64   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  65   _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 
  68   _gc_par_phases[MergeER] = new WorkerDataArray<double>(max_gc_threads, "Eager Reclaim (ms):");
  69 
  70   _gc_par_phases[MergeRS] = new WorkerDataArray<double>(max_gc_threads, "Remembered Sets (ms):");
  71   _merge_rs_merged_sparse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Sparse:");
  72   _gc_par_phases[MergeRS]->link_thread_work_items(_merge_rs_merged_sparse, MergeRSMergedSparse);
  73   _merge_rs_merged_fine = new WorkerDataArray<size_t>(max_gc_threads, "Merged Fine:");
  74   _gc_par_phases[MergeRS]->link_thread_work_items(_merge_rs_merged_fine, MergeRSMergedFine);
  75   _merge_rs_merged_coarse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Coarse:");
  76   _gc_par_phases[MergeRS]->link_thread_work_items(_merge_rs_merged_coarse, MergeRSMergedCoarse);
  77 
  78   _gc_par_phases[OptMergeRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Remembered Sets (ms):");
  79   _opt_merge_rs_merged_sparse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Sparse:");
  80   _gc_par_phases[OptMergeRS]->link_thread_work_items(_opt_merge_rs_merged_sparse, MergeRSMergedSparse);
  81   _opt_merge_rs_merged_fine = new WorkerDataArray<size_t>(max_gc_threads, "Merged Fine:");
  82   _gc_par_phases[OptMergeRS]->link_thread_work_items(_opt_merge_rs_merged_fine, MergeRSMergedFine);
  83   _opt_merge_rs_merged_coarse = new WorkerDataArray<size_t>(max_gc_threads, "Merged Coarse:");
  84   _gc_par_phases[OptMergeRS]->link_thread_work_items(_opt_merge_rs_merged_coarse, MergeRSMergedCoarse);
  85 
  86   _gc_par_phases[MergeLB] = new WorkerDataArray<double>(max_gc_threads, "Log Buffers (ms):");
  87   if (G1HotCardCache::default_use_cache()) {
  88     _gc_par_phases[MergeHCC] = new WorkerDataArray<double>(max_gc_threads, "Hot Card Cache (ms):");
  89     _merge_hcc_dirty_cards = new WorkerDataArray<size_t>(max_gc_threads, "Dirty Cards:");
  90     _gc_par_phases[MergeHCC]->link_thread_work_items(_merge_hcc_dirty_cards, MergeHCCDirtyCards);
  91     _merge_hcc_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  92     _gc_par_phases[MergeHCC]->link_thread_work_items(_merge_hcc_skipped_cards, MergeHCCSkippedCards);
  93   } else {
  94     _gc_par_phases[MergeHCC] = NULL;
  95     _merge_hcc_dirty_cards = NULL;
  96     _merge_hcc_skipped_cards = NULL;
  97   }
  98   _gc_par_phases[ScanHR] = new WorkerDataArray<double>(max_gc_threads, "Scan Heap Roots (ms):");
  99   _gc_par_phases[OptScanHR] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan Heap Roots (ms):");
 100   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scan (ms):");
 101   _gc_par_phases[OptCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Optional Code Root Scan (ms):");
 102   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
 103   _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):");
 104   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
 105   _gc_par_phases[OptTermination] = new WorkerDataArray<double>(max_gc_threads, "Optional Termination (ms):");
 106   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
 107   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
 108   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
 109 
 110   _scan_hr_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
 111   _gc_par_phases[ScanHR]->link_thread_work_items(_scan_hr_scanned_cards, ScanHRScannedCards);
 112   _scan_hr_scanned_blocks = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Blocks:");
 113   _gc_par_phases[ScanHR]->link_thread_work_items(_scan_hr_scanned_blocks, ScanHRScannedBlocks);
 114   _scan_hr_claimed_chunks = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Chunks:");
 115   _gc_par_phases[ScanHR]->link_thread_work_items(_scan_hr_claimed_chunks, ScanHRClaimedChunks);
 116 
 117   _opt_scan_hr_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
 118   _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_scanned_cards, ScanHRScannedCards);
 119   _opt_scan_hr_scanned_blocks = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Blocks:");
 120   _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_scanned_blocks, ScanHRScannedBlocks);
 121   _opt_scan_hr_claimed_chunks = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Chunks:");
 122   _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_claimed_chunks, ScanHRClaimedChunks);
 123   _opt_scan_hr_scanned_opt_refs = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Refs:");
 124   _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_scanned_opt_refs, ScanHRScannedOptRefs);
 125   _opt_scan_hr_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:");
 126   _gc_par_phases[OptScanHR]->link_thread_work_items(_opt_scan_hr_used_memory, ScanHRUsedMemory);
 127 
 128   _merge_lb_dirty_cards = new WorkerDataArray<size_t>(max_gc_threads, "Dirty Cards:");
 129   _gc_par_phases[MergeLB]->link_thread_work_items(_merge_lb_dirty_cards, MergeLBDirtyCards);
 130   _merge_lb_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
 131   _gc_par_phases[MergeLB]->link_thread_work_items(_merge_lb_skipped_cards, MergeLBSkippedCards);


 132 
 133   _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
 134   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
 135   _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
 136   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
 137 
 138   _opt_obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
 139   _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
 140   _opt_obj_copy_lab_undo_waste  = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
 141   _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
 142 
 143   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
 144   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 145 
 146   _opt_termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Optional Termination Attempts:");
 147   _gc_par_phases[OptTermination]->link_thread_work_items(_opt_termination_attempts);
 148 
 149   if (UseStringDeduplication) {
 150     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
 151     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
 152   } else {
 153     _gc_par_phases[StringDedupQueueFixup] = NULL;
 154     _gc_par_phases[StringDedupTableFixup] = NULL;
 155   }
 156 
 157   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
 158   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
 159   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 160 
 161   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
 162   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
 163 
 164   reset();
 165 }
 166 
 167 void G1GCPhaseTimes::reset() {
 168   _cur_collection_initial_evac_time_ms = 0.0;
 169   _cur_optional_evac_ms = 0.0;
 170   _cur_collection_code_root_fixup_time_ms = 0.0;
 171   _cur_strong_code_root_purge_time_ms = 0.0;
 172   _cur_merge_heap_roots_time_ms = 0.0;
 173   _cur_optional_merge_heap_roots_time_ms = 0.0;
 174   _cur_prepare_merge_heap_roots_time_ms = 0.0;
 175   _cur_optional_prepare_merge_heap_roots_time_ms = 0.0;
 176   _cur_evac_fail_recalc_used = 0.0;
 177   _cur_evac_fail_remove_self_forwards = 0.0;
 178   _cur_string_deduplication_time_ms = 0.0;
 179   _cur_prepare_tlab_time_ms = 0.0;
 180   _cur_resize_tlab_time_ms = 0.0;
 181   _cur_derived_pointer_table_update_time_ms = 0.0;
 182   _cur_clear_ct_time_ms = 0.0;
 183   _cur_expand_heap_time_ms = 0.0;
 184   _cur_ref_proc_time_ms = 0.0;
 185   _cur_collection_start_sec = 0.0;
 186   _root_region_scan_wait_time_ms = 0.0;
 187   _external_accounted_time_ms = 0.0;
 188   _recorded_prepare_heap_roots_time_ms = 0.0;
 189   _recorded_clear_claimed_marks_time_ms = 0.0;
 190   _recorded_young_cset_choice_time_ms = 0.0;
 191   _recorded_non_young_cset_choice_time_ms = 0.0;
 192   _recorded_redirty_logged_cards_time_ms = 0.0;
 193   _recorded_preserve_cm_referents_time_ms = 0.0;
 194   _recorded_merge_pss_time_ms = 0.0;
 195   _recorded_start_new_cset_time_ms = 0.0;
 196   _recorded_total_free_cset_time_ms = 0.0;
 197   _recorded_serial_free_cset_time_ms = 0.0;
 198   _cur_fast_reclaim_humongous_time_ms = 0.0;
 199   _cur_region_register_time = 0.0;
 200   _cur_fast_reclaim_humongous_total = 0;
 201   _cur_fast_reclaim_humongous_candidates = 0;
 202   _cur_fast_reclaim_humongous_reclaimed = 0;
 203   _cur_verify_before_time_ms = 0.0;
 204   _cur_verify_after_time_ms = 0.0;
 205 
 206   for (int i = 0; i < GCParPhasesSentinel; i++) {
 207     if (_gc_par_phases[i] != NULL) {
 208       _gc_par_phases[i]->reset();


 228   double value = _gc_par_phases[phase]->get(worker);
 229   if (value != WorkerDataArray<double>::uninitialized()) {
 230     return value;
 231   }
 232   return 0.0;
 233 }
 234 
 235 void G1GCPhaseTimes::note_gc_end() {
 236   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 237 
 238   double uninitialized = WorkerDataArray<double>::uninitialized();
 239 
 240   for (uint i = 0; i < _max_gc_threads; i++) {
 241     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 242     if (worker_start != uninitialized) {
 243       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 244       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 245       record_time_secs(GCWorkerTotal, i , total_worker_time);
 246 
 247       double worker_known_time = worker_time(ExtRootScan, i) +
 248                                  worker_time(ScanHR, i) +


 249                                  worker_time(CodeRoots, i) +
 250                                  worker_time(ObjCopy, i) +
 251                                  worker_time(Termination, i);
 252 
 253       record_time_secs(Other, i, total_worker_time - worker_known_time);
 254     } else {
 255       // Make sure all slots are uninitialized since this thread did not seem to have been started
 256       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 257       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 258       ASSERT_PHASE_UNINITIALIZED(MergeER);
 259       ASSERT_PHASE_UNINITIALIZED(MergeRS);
 260       ASSERT_PHASE_UNINITIALIZED(OptMergeRS);
 261       ASSERT_PHASE_UNINITIALIZED(MergeHCC);
 262       ASSERT_PHASE_UNINITIALIZED(MergeLB);
 263       ASSERT_PHASE_UNINITIALIZED(ScanHR);
 264       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 265       ASSERT_PHASE_UNINITIALIZED(OptCodeRoots);
 266       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 267       ASSERT_PHASE_UNINITIALIZED(OptObjCopy);
 268       ASSERT_PHASE_UNINITIALIZED(Termination);
 269     }
 270   }
 271 }
 272 
 273 #undef ASSERT_PHASE_UNINITIALIZED
 274 
 275 // record the time a phase took in seconds
 276 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 277   _gc_par_phases[phase]->set(worker_i, secs);
 278 }
 279 
 280 // add a number of seconds to a phase
 281 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 282   _gc_par_phases[phase]->add(worker_i, secs);
 283 }
 284 
 285 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 286   if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) {
 287     record_time_secs(phase, worker_i, secs);


 377     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 378   } else if (lt2.is_enabled()) {
 379     LogStream ls(lt2);
 380     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 381   }
 382 }
 383 
 384 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
 385   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
 386 }
 387 
 388 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 389   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
 390 }
 391 
 392 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 393   const double sum_ms = _root_region_scan_wait_time_ms +
 394                         _recorded_young_cset_choice_time_ms +
 395                         _recorded_non_young_cset_choice_time_ms +
 396                         _cur_region_register_time +
 397                         _recorded_prepare_heap_roots_time_ms +
 398                         _recorded_clear_claimed_marks_time_ms;
 399 
 400   info_time("Pre Evacuate Collection Set", sum_ms);
 401 
 402   if (_root_region_scan_wait_time_ms > 0.0) {
 403     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 404   }
 405   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
 406   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
 407   debug_time("Region Register", _cur_region_register_time);
 408   if (G1EagerReclaimHumongousObjects) {
 409     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
 410     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 411   }
 412 
 413   debug_time("Prepare Heap Roots", _recorded_prepare_heap_roots_time_ms);
 414   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
 415     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
 416   }
 417   return sum_ms;
 418 }
 419 
 420 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
 421   const double sum_ms = _cur_optional_evac_ms + _cur_optional_merge_heap_roots_time_ms;
 422   if (sum_ms > 0) {
 423     info_time("Merge Optional Heap Roots", _cur_optional_merge_heap_roots_time_ms);
 424 
 425     debug_time("Prepare Optional Merge Heap Roots", _cur_optional_prepare_merge_heap_roots_time_ms);
 426     debug_phase(_gc_par_phases[OptMergeRS]);
 427 
 428     info_time("Evacuate Optional Collection Set", _cur_optional_evac_ms);
 429     debug_phase(_gc_par_phases[OptScanHR]);
 430     debug_phase(_gc_par_phases[OptObjCopy]);
 431     debug_phase(_gc_par_phases[OptCodeRoots]);
 432     debug_phase(_gc_par_phases[OptTermination]);
 433   }
 434   return sum_ms;
 435 }
 436 
 437 double G1GCPhaseTimes::print_evacuate_initial_collection_set() const {
 438   info_time("Merge Heap Roots", _cur_merge_heap_roots_time_ms);
 439 
 440   debug_time("Prepare Merge Heap Roots", _cur_prepare_merge_heap_roots_time_ms);
 441   debug_phase(_gc_par_phases[MergeER]);
 442   debug_phase(_gc_par_phases[MergeRS]);
 443   if (G1HotCardCache::default_use_cache()) {
 444     debug_phase(_gc_par_phases[MergeHCC]);
 445   }
 446   debug_phase(_gc_par_phases[MergeLB]);
 447 
 448   info_time("Evacuate Collection Set", _cur_collection_initial_evac_time_ms);
 449 
 450   trace_phase(_gc_par_phases[GCWorkerStart], false);
 451   debug_phase(_gc_par_phases[ExtRootScan]);
 452   for (int i = ExtRootScanSubPhasesFirst; i <= ExtRootScanSubPhasesLast; i++) {
 453     trace_phase(_gc_par_phases[i]);
 454   }
 455   debug_phase(_gc_par_phases[ScanHR]);




 456   debug_phase(_gc_par_phases[CodeRoots]);
 457   debug_phase(_gc_par_phases[ObjCopy]);
 458   debug_phase(_gc_par_phases[Termination]);
 459   debug_phase(_gc_par_phases[Other]);
 460   debug_phase(_gc_par_phases[GCWorkerTotal]);
 461   trace_phase(_gc_par_phases[GCWorkerEnd], false);
 462 
 463   return _cur_collection_initial_evac_time_ms + _cur_merge_heap_roots_time_ms;
 464 }
 465 
 466 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
 467   const double evac_fail_handling = _cur_evac_fail_recalc_used +
 468                                     _cur_evac_fail_remove_self_forwards;
 469   const double sum_ms = evac_fail_handling +
 470                         _cur_collection_code_root_fixup_time_ms +
 471                         _recorded_preserve_cm_referents_time_ms +
 472                         _cur_ref_proc_time_ms +
 473                         (_weak_phase_times.total_time_sec() * MILLIUNITS) +
 474                         _cur_clear_ct_time_ms +
 475                         _recorded_merge_pss_time_ms +
 476                         _cur_strong_code_root_purge_time_ms +
 477                         _recorded_redirty_logged_cards_time_ms +
 478                         _recorded_total_free_cset_time_ms +
 479                         _cur_fast_reclaim_humongous_time_ms +
 480                         _cur_expand_heap_time_ms +
 481                         _cur_string_deduplication_time_ms;
 482 
 483   info_time("Post Evacuate Collection Set", sum_ms);


 526   }
 527   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
 528 
 529 
 530   return sum_ms;
 531 }
 532 
 533 void G1GCPhaseTimes::print_other(double accounted_ms) const {
 534   info_time("Other", _gc_pause_time_ms - accounted_ms);
 535 }
 536 
 537 void G1GCPhaseTimes::print() {
 538   note_gc_end();
 539 
 540   if (_cur_verify_before_time_ms > 0.0) {
 541     debug_time("Verify Before", _cur_verify_before_time_ms);
 542   }
 543 
 544   double accounted_ms = 0.0;
 545   accounted_ms += print_pre_evacuate_collection_set();
 546   accounted_ms += print_evacuate_initial_collection_set();
 547   accounted_ms += print_evacuate_optional_collection_set();
 548   accounted_ms += print_post_evacuate_collection_set();
 549   print_other(accounted_ms);
 550 
 551   if (_cur_verify_after_time_ms > 0.0) {
 552     debug_time("Verify After", _cur_verify_after_time_ms);
 553   }
 554 }
 555 
 556 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
 557   static const char* names[] = {
 558       "GCWorkerStart",
 559       "ExtRootScan",
 560       "ThreadRoots",
 561       "UniverseRoots",
 562       "JNIRoots",
 563       "ObjectSynchronizerRoots",
 564       "ManagementRoots",
 565       "SystemDictionaryRoots",
 566       "CLDGRoots",
 567       "JVMTIRoots",
 568       AOT_ONLY("AOTCodeRoots" COMMA)

 569       "CMRefRoots",
 570       "WaitForStrongCLD",
 571       "WeakCLDRoots",
 572       "MergeER",
 573       "MergeRS",
 574       "OptMergeRS",
 575       "MergeLB",
 576       "MergeHCC",
 577       "ScanHR",
 578       "OptScanHR",
 579       "CodeRoots",
 580       "OptCodeRoots",
 581       "ObjCopy",
 582       "OptObjCopy",
 583       "Termination",
 584       "OptTermination",
 585       "Other",
 586       "GCWorkerTotal",
 587       "GCWorkerEnd",
 588       "StringDedupQueueFixup",
 589       "StringDedupTableFixup",
 590       "RedirtyCards",
 591       "YoungFreeCSet",
 592       "NonYoungFreeCSet"
 593       //GCParPhasesSentinel only used to tell end of enum
 594       };
 595 
 596   STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
 597 
 598   return names[phase];


 605   _trim_time(trim_time),
 606   _stopped(false) {
 607 
 608   assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use");
 609 }
 610 
 611 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
 612   if (!_stopped) {
 613     stop();
 614   }
 615 }
 616 
 617 void G1EvacPhaseWithTrimTimeTracker::stop() {
 618   assert(!_stopped, "Should only be called once");
 619   _total_time += (Ticks::now() - _start) - _pss->trim_ticks();
 620   _trim_time += _pss->trim_ticks();
 621   _pss->reset_trim_ticks();
 622   _stopped = true;
 623 }
 624 
 625 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id, bool must_record) :
 626   _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event(), _must_record(must_record) {
 627   if (_phase_times != NULL) {
 628     _start_time = Ticks::now();
 629   }
 630 }
 631 
 632 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 633   if (_phase_times != NULL) {
 634     if (_must_record) {
 635       _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
 636     } else {
 637       _phase_times->record_or_add_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
 638     }
 639     _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
 640   }
 641 }
 642 
 643 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
 644                                                  G1ParScanThreadState* pss,
 645                                                  G1GCPhaseTimes::GCParPhases phase,
 646                                                  uint worker_id) :
 647   G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
 648   _total_time(),
 649   _trim_time(),
 650   _trim_tracker(pss, _total_time, _trim_time) {
 651 }
 652 
 653 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
 654   if (_phase_times != NULL) {
 655     // Explicitly stop the trim tracker since it's not yet destructed.
 656     _trim_tracker.stop();
 657     // Exclude trim time by increasing the start time.
 658     _start_time += _trim_time;


  44   _gc_start_counter(0),
  45   _gc_pause_time_ms(0.0),
  46   _ref_phase_times(gc_timer, max_gc_threads),
  47   _weak_phase_times(max_gc_threads)
  48 {
  49   assert(max_gc_threads > 0, "Must have some GC threads");
  50 
  51   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
  52   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
  53 
  54   // Root scanning phases
  55   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
  56   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  57   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  58   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  59   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  60   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  61   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  62   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  63   AOT_ONLY(_gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scan (ms):");)
  64   JVMCI_ONLY(_gc_par_phases[JVMCIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMCI Root Scan (ms):");)
  65   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  66   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
  67   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (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[OptScanRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan RS (ms):");
  77   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scan (ms):");
  78   _gc_par_phases[OptCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Optional Code Root Scan (ms):");
  79   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
  80   _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):");
  81   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
  82   _gc_par_phases[OptTermination] = new WorkerDataArray<double>(max_gc_threads, "Optional 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_scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  95   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_scanned_cards, ScanRSScannedCards);
  96   _opt_scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  97   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_claimed_cards, ScanRSClaimedCards);
  98   _opt_scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  99   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_skipped_cards, ScanRSSkippedCards);
 100   _opt_scan_rs_scanned_opt_refs = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Refs:");
 101   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_scanned_opt_refs, ScanRSScannedOptRefs);
 102   _opt_scan_rs_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:");
 103   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_scan_rs_used_memory, ScanRSUsedMemory);
 104 
 105   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
 106   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
 107   _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
 108   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
 109   _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
 110   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
 111 
 112   _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
 113   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
 114   _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
 115   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
 116 
 117   _opt_obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
 118   _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
 119   _opt_obj_copy_lab_undo_waste  = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
 120   _gc_par_phases[OptObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
 121 
 122   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
 123   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 124 
 125   _opt_termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Optional Termination Attempts:");
 126   _gc_par_phases[OptTermination]->link_thread_work_items(_opt_termination_attempts);
 127 
 128   if (UseStringDeduplication) {
 129     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
 130     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
 131   } else {
 132     _gc_par_phases[StringDedupQueueFixup] = NULL;
 133     _gc_par_phases[StringDedupTableFixup] = NULL;
 134   }
 135 
 136   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
 137   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
 138   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 139 
 140   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
 141   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
 142 
 143   reset();
 144 }
 145 
 146 void G1GCPhaseTimes::reset() {
 147   _cur_collection_initial_evac_time_ms = 0.0;
 148   _cur_optional_evac_ms = 0.0;
 149   _cur_collection_code_root_fixup_time_ms = 0.0;
 150   _cur_strong_code_root_purge_time_ms = 0.0;




 151   _cur_evac_fail_recalc_used = 0.0;
 152   _cur_evac_fail_remove_self_forwards = 0.0;
 153   _cur_string_deduplication_time_ms = 0.0;
 154   _cur_prepare_tlab_time_ms = 0.0;
 155   _cur_resize_tlab_time_ms = 0.0;
 156   _cur_derived_pointer_table_update_time_ms = 0.0;
 157   _cur_clear_ct_time_ms = 0.0;
 158   _cur_expand_heap_time_ms = 0.0;
 159   _cur_ref_proc_time_ms = 0.0;
 160   _cur_collection_start_sec = 0.0;
 161   _root_region_scan_wait_time_ms = 0.0;
 162   _external_accounted_time_ms = 0.0;

 163   _recorded_clear_claimed_marks_time_ms = 0.0;
 164   _recorded_young_cset_choice_time_ms = 0.0;
 165   _recorded_non_young_cset_choice_time_ms = 0.0;
 166   _recorded_redirty_logged_cards_time_ms = 0.0;
 167   _recorded_preserve_cm_referents_time_ms = 0.0;
 168   _recorded_merge_pss_time_ms = 0.0;
 169   _recorded_start_new_cset_time_ms = 0.0;
 170   _recorded_total_free_cset_time_ms = 0.0;
 171   _recorded_serial_free_cset_time_ms = 0.0;
 172   _cur_fast_reclaim_humongous_time_ms = 0.0;
 173   _cur_region_register_time = 0.0;
 174   _cur_fast_reclaim_humongous_total = 0;
 175   _cur_fast_reclaim_humongous_candidates = 0;
 176   _cur_fast_reclaim_humongous_reclaimed = 0;
 177   _cur_verify_before_time_ms = 0.0;
 178   _cur_verify_after_time_ms = 0.0;
 179 
 180   for (int i = 0; i < GCParPhasesSentinel; i++) {
 181     if (_gc_par_phases[i] != NULL) {
 182       _gc_par_phases[i]->reset();


 202   double value = _gc_par_phases[phase]->get(worker);
 203   if (value != WorkerDataArray<double>::uninitialized()) {
 204     return value;
 205   }
 206   return 0.0;
 207 }
 208 
 209 void G1GCPhaseTimes::note_gc_end() {
 210   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 211 
 212   double uninitialized = WorkerDataArray<double>::uninitialized();
 213 
 214   for (uint i = 0; i < _max_gc_threads; i++) {
 215     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
 216     if (worker_start != uninitialized) {
 217       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
 218       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
 219       record_time_secs(GCWorkerTotal, i , total_worker_time);
 220 
 221       double worker_known_time = worker_time(ExtRootScan, i) +
 222                                  worker_time(ScanHCC, i) +
 223                                  worker_time(UpdateRS, i) +
 224                                  worker_time(ScanRS, i) +
 225                                  worker_time(CodeRoots, i) +
 226                                  worker_time(ObjCopy, i) +
 227                                  worker_time(Termination, i);
 228 
 229       record_time_secs(Other, i, total_worker_time - worker_known_time);
 230     } else {
 231       // Make sure all slots are uninitialized since this thread did not seem to have been started
 232       ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
 233       ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
 234       ASSERT_PHASE_UNINITIALIZED(ScanHCC);
 235       ASSERT_PHASE_UNINITIALIZED(UpdateRS);
 236       ASSERT_PHASE_UNINITIALIZED(ScanRS);



 237       ASSERT_PHASE_UNINITIALIZED(CodeRoots);

 238       ASSERT_PHASE_UNINITIALIZED(ObjCopy);

 239       ASSERT_PHASE_UNINITIALIZED(Termination);
 240     }
 241   }
 242 }
 243 
 244 #undef ASSERT_PHASE_UNINITIALIZED
 245 
 246 // record the time a phase took in seconds
 247 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 248   _gc_par_phases[phase]->set(worker_i, secs);
 249 }
 250 
 251 // add a number of seconds to a phase
 252 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 253   _gc_par_phases[phase]->add(worker_i, secs);
 254 }
 255 
 256 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 257   if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) {
 258     record_time_secs(phase, worker_i, secs);


 348     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 349   } else if (lt2.is_enabled()) {
 350     LogStream ls(lt2);
 351     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 352   }
 353 }
 354 
 355 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
 356   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
 357 }
 358 
 359 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 360   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
 361 }
 362 
 363 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 364   const double sum_ms = _root_region_scan_wait_time_ms +
 365                         _recorded_young_cset_choice_time_ms +
 366                         _recorded_non_young_cset_choice_time_ms +
 367                         _cur_region_register_time +

 368                         _recorded_clear_claimed_marks_time_ms;
 369 
 370   info_time("Pre Evacuate Collection Set", sum_ms);
 371 
 372   if (_root_region_scan_wait_time_ms > 0.0) {
 373     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 374   }
 375   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
 376   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
 377   debug_time("Region Register", _cur_region_register_time);
 378   if (G1EagerReclaimHumongousObjects) {
 379     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
 380     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 381   }
 382 

 383   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
 384     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
 385   }
 386   return sum_ms;
 387 }
 388 
 389 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
 390   const double sum_ms = _cur_optional_evac_ms;
 391   if (sum_ms > 0) {
 392     info_time("Evacuate Optional Collection Set", sum_ms);
 393     debug_phase(_gc_par_phases[OptScanRS]);





 394     debug_phase(_gc_par_phases[OptObjCopy]);
 395     debug_phase(_gc_par_phases[OptCodeRoots]);
 396     debug_phase(_gc_par_phases[OptTermination]);
 397   }
 398   return sum_ms;
 399 }
 400 
 401 double G1GCPhaseTimes::print_evacuate_collection_set() const {
 402   const double sum_ms = _cur_collection_initial_evac_time_ms;








 403 
 404   info_time("Evacuate Collection Set", sum_ms);
 405 
 406   trace_phase(_gc_par_phases[GCWorkerStart], false);
 407   debug_phase(_gc_par_phases[ExtRootScan]);
 408   for (int i = ExtRootScanSubPhasesFirst; i <= ExtRootScanSubPhasesLast; i++) {
 409     trace_phase(_gc_par_phases[i]);
 410   }
 411   if (G1HotCardCache::default_use_cache()) {
 412     debug_phase(_gc_par_phases[ScanHCC]);
 413   }
 414   debug_phase(_gc_par_phases[UpdateRS]);
 415   debug_phase(_gc_par_phases[ScanRS]);
 416   debug_phase(_gc_par_phases[CodeRoots]);
 417   debug_phase(_gc_par_phases[ObjCopy]);
 418   debug_phase(_gc_par_phases[Termination]);
 419   debug_phase(_gc_par_phases[Other]);
 420   debug_phase(_gc_par_phases[GCWorkerTotal]);
 421   trace_phase(_gc_par_phases[GCWorkerEnd], false);
 422 
 423   return sum_ms;
 424 }
 425 
 426 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
 427   const double evac_fail_handling = _cur_evac_fail_recalc_used +
 428                                     _cur_evac_fail_remove_self_forwards;
 429   const double sum_ms = evac_fail_handling +
 430                         _cur_collection_code_root_fixup_time_ms +
 431                         _recorded_preserve_cm_referents_time_ms +
 432                         _cur_ref_proc_time_ms +
 433                         (_weak_phase_times.total_time_sec() * MILLIUNITS) +
 434                         _cur_clear_ct_time_ms +
 435                         _recorded_merge_pss_time_ms +
 436                         _cur_strong_code_root_purge_time_ms +
 437                         _recorded_redirty_logged_cards_time_ms +
 438                         _recorded_total_free_cset_time_ms +
 439                         _cur_fast_reclaim_humongous_time_ms +
 440                         _cur_expand_heap_time_ms +
 441                         _cur_string_deduplication_time_ms;
 442 
 443   info_time("Post Evacuate Collection Set", sum_ms);


 486   }
 487   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
 488 
 489 
 490   return sum_ms;
 491 }
 492 
 493 void G1GCPhaseTimes::print_other(double accounted_ms) const {
 494   info_time("Other", _gc_pause_time_ms - accounted_ms);
 495 }
 496 
 497 void G1GCPhaseTimes::print() {
 498   note_gc_end();
 499 
 500   if (_cur_verify_before_time_ms > 0.0) {
 501     debug_time("Verify Before", _cur_verify_before_time_ms);
 502   }
 503 
 504   double accounted_ms = 0.0;
 505   accounted_ms += print_pre_evacuate_collection_set();
 506   accounted_ms += print_evacuate_collection_set();
 507   accounted_ms += print_evacuate_optional_collection_set();
 508   accounted_ms += print_post_evacuate_collection_set();
 509   print_other(accounted_ms);
 510 
 511   if (_cur_verify_after_time_ms > 0.0) {
 512     debug_time("Verify After", _cur_verify_after_time_ms);
 513   }
 514 }
 515 
 516 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
 517   static const char* names[] = {
 518       "GCWorkerStart",
 519       "ExtRootScan",
 520       "ThreadRoots",
 521       "UniverseRoots",
 522       "JNIRoots",
 523       "ObjectSynchronizerRoots",
 524       "ManagementRoots",
 525       "SystemDictionaryRoots",
 526       "CLDGRoots",
 527       "JVMTIRoots",
 528       AOT_ONLY("AOTCodeRoots" COMMA)
 529       JVMCI_ONLY("JVMCIRoots" COMMA)
 530       "CMRefRoots",
 531       "WaitForStrongCLD",
 532       "WeakCLDRoots",
 533       "UpdateRS",
 534       "ScanHCC",
 535       "ScanRS",
 536       "OptScanRS",



 537       "CodeRoots",
 538       "OptCodeRoots",
 539       "ObjCopy",
 540       "OptObjCopy",
 541       "Termination",
 542       "OptTermination",
 543       "Other",
 544       "GCWorkerTotal",
 545       "GCWorkerEnd",
 546       "StringDedupQueueFixup",
 547       "StringDedupTableFixup",
 548       "RedirtyCards",
 549       "YoungFreeCSet",
 550       "NonYoungFreeCSet"
 551       //GCParPhasesSentinel only used to tell end of enum
 552       };
 553 
 554   STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
 555 
 556   return names[phase];


 563   _trim_time(trim_time),
 564   _stopped(false) {
 565 
 566   assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use");
 567 }
 568 
 569 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
 570   if (!_stopped) {
 571     stop();
 572   }
 573 }
 574 
 575 void G1EvacPhaseWithTrimTimeTracker::stop() {
 576   assert(!_stopped, "Should only be called once");
 577   _total_time += (Ticks::now() - _start) - _pss->trim_ticks();
 578   _trim_time += _pss->trim_ticks();
 579   _pss->reset_trim_ticks();
 580   _stopped = true;
 581 }
 582 
 583 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
 584   _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event() {
 585   if (_phase_times != NULL) {
 586     _start_time = Ticks::now();
 587   }
 588 }
 589 
 590 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
 591   if (_phase_times != NULL) {
 592     _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());




 593     _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
 594   }
 595 }
 596 
 597 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
 598                                                  G1ParScanThreadState* pss,
 599                                                  G1GCPhaseTimes::GCParPhases phase,
 600                                                  uint worker_id) :
 601   G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
 602   _total_time(),
 603   _trim_time(),
 604   _trim_tracker(pss, _total_time, _trim_time) {
 605 }
 606 
 607 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
 608   if (_phase_times != NULL) {
 609     // Explicitly stop the trim tracker since it's not yet destructed.
 610     _trim_tracker.stop();
 611     // Exclude trim time by increasing the start time.
 612     _start_time += _trim_time;
< prev index next >