< prev index next >

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

Print this page




  43   _max_gc_threads(max_gc_threads),
  44   _gc_start_counter(0),
  45   _gc_pause_time_ms(0.0),
  46   _ref_phase_times(gc_timer, max_gc_threads),
  47   _weak_phase_times(max_gc_threads)
  48 {
  49   assert(max_gc_threads > 0, "Must have some GC threads");
  50 
  51   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
  52   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
  53 
  54   // Root scanning phases
  55   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
  56   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  57   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  58   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  59   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  60   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  61   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  62   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  63   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();
 183     }
 184   }
 185 
 186   _ref_phase_times.reset();
 187   _weak_phase_times.reset();
 188 }
 189 
 190 void G1GCPhaseTimes::note_gc_start() {
 191   _gc_start_counter = os::elapsed_counter();
 192   reset();
 193 }


 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);
 259   } else {
 260     add_time_secs(phase, worker_i, secs);
 261   }
 262 }
 263 
 264 double G1GCPhaseTimes::get_time_secs(GCParPhases phase, uint worker_i) {
 265   return _gc_par_phases[phase]->get(worker_i);
 266 }
 267 
 268 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 269   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 270 }
 271 
 272 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 273   _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index);
 274 }
 275 
 276 size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i, uint index) {
 277   return _gc_par_phases[phase]->get_thread_work_item(worker_i, index);
 278 }
 279 
 280 // return the average time for a phase in milliseconds
 281 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 282   return _gc_par_phases[phase]->average() * 1000.0;
 283 }
 284 
 285 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 286   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 287   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 288 }
 289 
 290 template <class T>
 291 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 292   LogTarget(Trace, gc, phases, task) lt;
 293   if (lt.is_enabled()) {
 294     LogStream ls(lt);
 295     ls.print("%s", indent);
 296     phase->print_details_on(&ls);
 297   }
 298 }
 299 


 347     LogStream ls(lt);
 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;


 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];
 557 }
 558 
 559 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
 560   _pss(pss),
 561   _start(Ticks::now()),
 562   _total_time(total_time),




  43   _max_gc_threads(max_gc_threads),
  44   _gc_start_counter(0),
  45   _gc_pause_time_ms(0.0),
  46   _ref_phase_times(gc_timer, max_gc_threads),
  47   _weak_phase_times(max_gc_threads)
  48 {
  49   assert(max_gc_threads > 0, "Must have some GC threads");
  50 
  51   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
  52   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
  53 
  54   // Root scanning phases
  55   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
  56   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  57   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  58   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  59   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  60   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  61   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  62   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  63 #if INCLUDE_AOT
  64   _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scan (ms):");
  65 #endif
  66   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  67   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
  68   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
  69   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
  70 
  71   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
  72   if (G1HotCardCache::default_use_cache()) {
  73     _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
  74   } else {
  75     _gc_par_phases[ScanHCC] = NULL;
  76   }
  77   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");
  78   _gc_par_phases[OptScanRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan RS (ms):");
  79   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");

  80   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
  81   _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):");
  82   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");

  83   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
  84   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
  85   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
  86 
  87   _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  88   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
  89   _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  90   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
  91   _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  92   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
  93 
  94   _opt_cset_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  95   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_scanned_cards, OptCSetScannedCards);
  96   _opt_cset_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  97   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_claimed_cards, OptCSetClaimedCards);
  98   _opt_cset_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  99   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_skipped_cards, OptCSetSkippedCards);
 100   _opt_cset_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:");
 101   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_used_memory, OptCSetUsedMemory);


 102 
 103   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
 104   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
 105   _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
 106   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
 107   _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
 108   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
 109 
 110   _obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
 111   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
 112   _obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
 113   _gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
 114 





 115   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
 116   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 117 



 118   if (UseStringDeduplication) {
 119     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
 120     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
 121   } else {
 122     _gc_par_phases[StringDedupQueueFixup] = NULL;
 123     _gc_par_phases[StringDedupTableFixup] = NULL;
 124   }
 125 
 126   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
 127   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
 128   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 129 
 130   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
 131   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
 132 
 133   reset();
 134 }
 135 
 136 void G1GCPhaseTimes::reset() {
 137   _cur_collection_par_time_ms = 0.0;
 138   _cur_optional_evac_ms = 0.0;
 139   _cur_collection_code_root_fixup_time_ms = 0.0;
 140   _cur_strong_code_root_purge_time_ms = 0.0;
 141   _cur_evac_fail_recalc_used = 0.0;
 142   _cur_evac_fail_remove_self_forwards = 0.0;
 143   _cur_string_deduplication_time_ms = 0.0;
 144   _cur_prepare_tlab_time_ms = 0.0;
 145   _cur_resize_tlab_time_ms = 0.0;
 146   _cur_derived_pointer_table_update_time_ms = 0.0;
 147   _cur_clear_ct_time_ms = 0.0;
 148   _cur_expand_heap_time_ms = 0.0;
 149   _cur_ref_proc_time_ms = 0.0;
 150   _cur_collection_start_sec = 0.0;
 151   _root_region_scan_wait_time_ms = 0.0;
 152   _external_accounted_time_ms = 0.0;
 153   _recorded_clear_claimed_marks_time_ms = 0.0;
 154   _recorded_young_cset_choice_time_ms = 0.0;
 155   _recorded_non_young_cset_choice_time_ms = 0.0;
 156   _recorded_redirty_logged_cards_time_ms = 0.0;
 157   _recorded_preserve_cm_referents_time_ms = 0.0;
 158   _recorded_merge_pss_time_ms = 0.0;
 159   _recorded_start_new_cset_time_ms = 0.0;
 160   _recorded_total_free_cset_time_ms = 0.0;
 161   _recorded_serial_free_cset_time_ms = 0.0;
 162   _cur_fast_reclaim_humongous_time_ms = 0.0;
 163   _cur_fast_reclaim_humongous_register_time_ms = 0.0;
 164   _cur_fast_reclaim_humongous_total = 0;
 165   _cur_fast_reclaim_humongous_candidates = 0;
 166   _cur_fast_reclaim_humongous_reclaimed = 0;
 167   _cur_verify_before_time_ms = 0.0;
 168   _cur_verify_after_time_ms = 0.0;
 169 
 170   for (int i = 0; i < GCParPhasesSentinel; i++) {
 171     if (_gc_par_phases[i] != NULL) {
 172       _gc_par_phases[i]->reset();
 173     }
 174   }
 175 
 176   _ref_phase_times.reset();
 177   _weak_phase_times.reset();
 178 }
 179 
 180 void G1GCPhaseTimes::note_gc_start() {
 181   _gc_start_counter = os::elapsed_counter();
 182   reset();
 183 }


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




 254 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 255   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 256 }
 257 
 258 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 259   _gc_par_phases[phase]->set_or_add_thread_work_item(worker_i, count, index);
 260 }
 261 




 262 // return the average time for a phase in milliseconds
 263 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 264   return _gc_par_phases[phase]->average() * 1000.0;
 265 }
 266 
 267 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 268   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 269   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 270 }
 271 
 272 template <class T>
 273 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 274   LogTarget(Trace, gc, phases, task) lt;
 275   if (lt.is_enabled()) {
 276     LogStream ls(lt);
 277     ls.print("%s", indent);
 278     phase->print_details_on(&ls);
 279   }
 280 }
 281 


 329     LogStream ls(lt);
 330     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 331   } else if (lt2.is_enabled()) {
 332     LogStream ls(lt2);
 333     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 334   }
 335 }
 336 
 337 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
 338   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
 339 }
 340 
 341 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 342   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
 343 }
 344 
 345 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 346   const double sum_ms = _root_region_scan_wait_time_ms +
 347                         _recorded_young_cset_choice_time_ms +
 348                         _recorded_non_young_cset_choice_time_ms +
 349                         _cur_fast_reclaim_humongous_register_time_ms +
 350                         _recorded_clear_claimed_marks_time_ms;
 351 
 352   info_time("Pre Evacuate Collection Set", sum_ms);
 353 
 354   if (_root_region_scan_wait_time_ms > 0.0) {
 355     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 356   }
 357   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
 358   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));

 359   if (G1EagerReclaimHumongousObjects) {
 360     debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 361     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
 362     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 363   }
 364 
 365   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
 366     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
 367   }
 368   return sum_ms;
 369 }
 370 
 371 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
 372   const double sum_ms = _cur_optional_evac_ms;
 373   if (sum_ms > 0) {
 374     info_time("Evacuate Optional Collection Set", sum_ms);
 375     debug_phase(_gc_par_phases[OptScanRS]);
 376     debug_phase(_gc_par_phases[OptObjCopy]);


 377   }
 378   return sum_ms;
 379 }
 380 
 381 double G1GCPhaseTimes::print_evacuate_collection_set() const {
 382   const double sum_ms = _cur_collection_par_time_ms;
 383 
 384   info_time("Evacuate Collection Set", sum_ms);
 385 
 386   trace_phase(_gc_par_phases[GCWorkerStart], false);
 387   debug_phase(_gc_par_phases[ExtRootScan]);
 388   for (int i = ExtRootScanSubPhasesStart; i <= ExtRootScanSubPhasesEnd; i++) {
 389     trace_phase(_gc_par_phases[i]);
 390   }
 391   if (G1HotCardCache::default_use_cache()) {
 392     debug_phase(_gc_par_phases[ScanHCC]);
 393   }
 394   debug_phase(_gc_par_phases[UpdateRS]);
 395   debug_phase(_gc_par_phases[ScanRS]);
 396   debug_phase(_gc_par_phases[CodeRoots]);
 397   debug_phase(_gc_par_phases[ObjCopy]);
 398   debug_phase(_gc_par_phases[Termination]);
 399   debug_phase(_gc_par_phases[Other]);
 400   debug_phase(_gc_par_phases[GCWorkerTotal]);
 401   trace_phase(_gc_par_phases[GCWorkerEnd], false);
 402 
 403   return sum_ms;
 404 }
 405 
 406 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
 407   const double evac_fail_handling = _cur_evac_fail_recalc_used +
 408                                     _cur_evac_fail_remove_self_forwards;


 488   accounted_ms += print_post_evacuate_collection_set();
 489   print_other(accounted_ms);
 490 
 491   if (_cur_verify_after_time_ms > 0.0) {
 492     debug_time("Verify After", _cur_verify_after_time_ms);
 493   }
 494 }
 495 
 496 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
 497   static const char* names[] = {
 498       "GCWorkerStart",
 499       "ExtRootScan",
 500       "ThreadRoots",
 501       "UniverseRoots",
 502       "JNIRoots",
 503       "ObjectSynchronizerRoots",
 504       "ManagementRoots",
 505       "SystemDictionaryRoots",
 506       "CLDGRoots",
 507       "JVMTIRoots",
 508 #if INCLUDE_AOT
 509       "AOTCodeRoots",
 510 #endif
 511       "CMRefRoots",
 512       "WaitForStrongCLD",
 513       "WeakCLDRoots",
 514       "SATBFiltering",
 515       "UpdateRS",
 516       "ScanHCC",
 517       "ScanRS",
 518       "OptScanRS",
 519       "CodeRoots",

 520       "ObjCopy",
 521       "OptObjCopy",
 522       "Termination",

 523       "Other",
 524       "GCWorkerTotal",
 525       "GCWorkerEnd",
 526       "StringDedupQueueFixup",
 527       "StringDedupTableFixup",
 528       "RedirtyCards",
 529       "YoungFreeCSet",
 530       "NonYoungFreeCSet"
 531       //GCParPhasesSentinel only used to tell end of enum
 532       };
 533 
 534   STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
 535 
 536   return names[phase];
 537 }
 538 
 539 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
 540   _pss(pss),
 541   _start(Ticks::now()),
 542   _total_time(total_time),


< prev index next >