< prev index next >

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

Print this page
rev 52675 : 8213890: Implementation of JEP 344: Abortable Mixed Collections for G1
Reviewed-by:
Contributed-by: erik.helin@oracle.com, stefan.johansson@oracle.com
rev 52676 : imported patch AMGC-impl
rev 52679 : imported patch AMGC-tsch-rev1-log


  56   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
  57   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  58   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  59   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  60   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  61   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  62   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  63   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  64   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  65   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
  66   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
  67   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
  68 
  69   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
  70   if (G1HotCardCache::default_use_cache()) {
  71     _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
  72   } else {
  73     _gc_par_phases[ScanHCC] = NULL;
  74   }
  75   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");

  76   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");
  77 #if INCLUDE_AOT
  78   _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scanning (ms):");
  79 #endif
  80   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");

  81   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
  82   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
  83   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
  84   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
  85 
  86   _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  87   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
  88   _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  89   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
  90   _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  91   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
  92 









  93   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
  94   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
  95   _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  96   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
  97   _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  98   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
  99 
 100   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
 101   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 102 
 103   if (UseStringDeduplication) {
 104     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
 105     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
 106   } else {
 107     _gc_par_phases[StringDedupQueueFixup] = NULL;
 108     _gc_par_phases[StringDedupTableFixup] = NULL;
 109   }
 110 
 111   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
 112   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
 113   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 114 
 115   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
 116   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
 117 
 118   reset();
 119 }
 120 
 121 void G1GCPhaseTimes::reset() {
 122   _cur_collection_par_time_ms = 0.0;

 123   _cur_collection_code_root_fixup_time_ms = 0.0;
 124   _cur_strong_code_root_purge_time_ms = 0.0;
 125   _cur_evac_fail_recalc_used = 0.0;
 126   _cur_evac_fail_remove_self_forwards = 0.0;
 127   _cur_string_dedup_fixup_time_ms = 0.0;
 128   _cur_prepare_tlab_time_ms = 0.0;
 129   _cur_resize_tlab_time_ms = 0.0;
 130   _cur_derived_pointer_table_update_time_ms = 0.0;
 131   _cur_clear_ct_time_ms = 0.0;
 132   _cur_expand_heap_time_ms = 0.0;
 133   _cur_ref_proc_time_ms = 0.0;
 134   _cur_collection_start_sec = 0.0;
 135   _root_region_scan_wait_time_ms = 0.0;
 136   _external_accounted_time_ms = 0.0;
 137   _recorded_clear_claimed_marks_time_ms = 0.0;
 138   _recorded_young_cset_choice_time_ms = 0.0;
 139   _recorded_non_young_cset_choice_time_ms = 0.0;
 140   _recorded_redirty_logged_cards_time_ms = 0.0;
 141   _recorded_preserve_cm_referents_time_ms = 0.0;
 142   _recorded_merge_pss_time_ms = 0.0;


 210       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 211       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 212       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 213       ASSERT_PHASE_UNINITIALIZED(Termination);
 214     }
 215   }
 216 }
 217 
 218 #undef ASSERT_PHASE_UNINITIALIZED
 219 
 220 // record the time a phase took in seconds
 221 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 222   _gc_par_phases[phase]->set(worker_i, secs);
 223 }
 224 
 225 // add a number of seconds to a phase
 226 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 227   _gc_par_phases[phase]->add(worker_i, secs);
 228 }
 229 
 230 void G1GCPhaseTimes::record_or_add_objcopy_time_secs(uint worker_i, double secs) {
 231   if (_gc_par_phases[ObjCopy]->get(worker_i) == _gc_par_phases[ObjCopy]->uninitialized()) {
 232     record_time_secs(ObjCopy, worker_i, secs);
 233   } else {
 234     add_time_secs(ObjCopy, worker_i, secs);
 235   }
 236 }
 237 
 238 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 239   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 240 }
 241 
 242 // return the average time for a phase in milliseconds
 243 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 244   return _gc_par_phases[phase]->average() * 1000.0;
 245 }
 246 
 247 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 248   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 249   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 250 }
 251 
 252 template <class T>
 253 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 254   LogTarget(Trace, gc, phases, task) lt;


 331 
 332   info_time("Pre Evacuate Collection Set", sum_ms);
 333 
 334   if (_root_region_scan_wait_time_ms > 0.0) {
 335     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 336   }
 337   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
 338   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
 339   if (G1EagerReclaimHumongousObjects) {
 340     debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 341     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
 342     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 343   }
 344 
 345   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
 346     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
 347   }
 348   return sum_ms;
 349 }
 350 










 351 double G1GCPhaseTimes::print_evacuate_collection_set() const {
 352   const double sum_ms = _cur_collection_par_time_ms;
 353 
 354   info_time("Evacuate Collection Set", sum_ms);
 355 
 356   trace_phase(_gc_par_phases[GCWorkerStart], false);
 357   debug_phase(_gc_par_phases[ExtRootScan]);
 358   for (int i = ThreadRoots; i <= SATBFiltering; i++) {
 359     trace_phase(_gc_par_phases[i]);
 360   }
 361   debug_phase(_gc_par_phases[UpdateRS]);
 362   if (G1HotCardCache::default_use_cache()) {
 363     trace_phase(_gc_par_phases[ScanHCC]);
 364   }
 365   debug_phase(_gc_par_phases[ScanRS]);
 366   debug_phase(_gc_par_phases[CodeRoots]);
 367 #if INCLUDE_AOT
 368   debug_phase(_gc_par_phases[AOTCodeRoots]);
 369 #endif
 370   debug_phase(_gc_par_phases[ObjCopy]);


 440   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
 441 
 442 
 443   return sum_ms;
 444 }
 445 
 446 void G1GCPhaseTimes::print_other(double accounted_ms) const {
 447   info_time("Other", _gc_pause_time_ms - accounted_ms);
 448 }
 449 
 450 void G1GCPhaseTimes::print() {
 451   note_gc_end();
 452 
 453   if (_cur_verify_before_time_ms > 0.0) {
 454     debug_time("Verify Before", _cur_verify_before_time_ms);
 455   }
 456 
 457   double accounted_ms = 0.0;
 458   accounted_ms += print_pre_evacuate_collection_set();
 459   accounted_ms += print_evacuate_collection_set();

 460   accounted_ms += print_post_evacuate_collection_set();
 461   print_other(accounted_ms);
 462 
 463   if (_cur_verify_after_time_ms > 0.0) {
 464     debug_time("Verify After", _cur_verify_after_time_ms);
 465   }
 466 }
 467 
 468 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
 469   static const char* names[] = {
 470       "GCWorkerStart",
 471       "ExtRootScan",
 472       "ThreadRoots",
 473       "StringTableRoots",
 474       "UniverseRoots",
 475       "JNIRoots",
 476       "ObjectSynchronizerRoots",
 477       "ManagementRoots",
 478       "SystemDictionaryRoots",
 479       "CLDGRoots",
 480       "JVMTIRoots",
 481       "CMRefRoots",
 482       "WaitForStrongCLD",
 483       "WeakCLDRoots",
 484       "SATBFiltering",
 485       "UpdateRS",
 486       "ScanHCC",
 487       "ScanRS",

 488       "CodeRoots",
 489 #if INCLUDE_AOT
 490       "AOTCodeRoots",
 491 #endif
 492       "ObjCopy",

 493       "Termination",
 494       "Other",
 495       "GCWorkerTotal",
 496       "GCWorkerEnd",
 497       "StringDedupQueueFixup",
 498       "StringDedupTableFixup",
 499       "RedirtyCards",
 500       "YoungFreeCSet",
 501       "NonYoungFreeCSet"
 502       //GCParPhasesSentinel only used to tell end of enum
 503       };
 504 
 505   STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
 506 
 507   return names[phase];
 508 }
 509 
 510 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
 511   _pss(pss),
 512   _start(Ticks::now()),


 544     _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
 545   }
 546 }
 547 
 548 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
 549                                                  G1ParScanThreadState* pss,
 550                                                  G1GCPhaseTimes::GCParPhases phase,
 551                                                  uint worker_id) :
 552   G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
 553   _total_time(),
 554   _trim_time(),
 555   _trim_tracker(pss, _total_time, _trim_time) {
 556 }
 557 
 558 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
 559   if (_phase_times != NULL) {
 560     // Explicitly stop the trim tracker since it's not yet destructed.
 561     _trim_tracker.stop();
 562     // Exclude trim time by increasing the start time.
 563     _start_time += _trim_time;
 564     _phase_times->record_or_add_objcopy_time_secs(_worker_id, _trim_time.seconds());
 565   }
 566 }
 567 


  56   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
  57   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  58   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  59   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  60   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  61   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  62   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  63   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  64   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  65   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
  66   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");
  67   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):");
  68 
  69   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):");
  70   if (G1HotCardCache::default_use_cache()) {
  71     _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):");
  72   } else {
  73     _gc_par_phases[ScanHCC] = NULL;
  74   }
  75   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):");
  76   _gc_par_phases[OptScanRS] = new WorkerDataArray<double>(max_gc_threads, "Optional Scan RS (ms):");
  77   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):");
  78 #if INCLUDE_AOT
  79   _gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>(max_gc_threads, "AOT Root Scanning (ms):");
  80 #endif
  81   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):");
  82   _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Optional Object Copy (ms):");
  83   _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):");
  84   _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):");
  85   _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):");
  86   _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):");
  87 
  88   _scan_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  89   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_scanned_cards, ScanRSScannedCards);
  90   _scan_rs_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  91   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_claimed_cards, ScanRSClaimedCards);
  92   _scan_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
  93   _gc_par_phases[ScanRS]->link_thread_work_items(_scan_rs_skipped_cards, ScanRSSkippedCards);
  94 
  95   _opt_cset_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
  96   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_scanned_cards, OptCSetScannedCards);
  97   _opt_cset_claimed_cards = new WorkerDataArray<size_t>(max_gc_threads, "Claimed Cards:");
  98   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_claimed_cards, OptCSetClaimedCards);
  99   _opt_cset_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
 100   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_skipped_cards, OptCSetSkippedCards);
 101   _opt_cset_used_memory = new WorkerDataArray<size_t>(max_gc_threads, "Used Memory:");
 102   _gc_par_phases[OptScanRS]->link_thread_work_items(_opt_cset_used_memory, OptCSetUsedMemory);
 103 
 104   _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:");
 105   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers, UpdateRSProcessedBuffers);
 106   _update_rs_scanned_cards = new WorkerDataArray<size_t>(max_gc_threads, "Scanned Cards:");
 107   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_scanned_cards, UpdateRSScannedCards);
 108   _update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
 109   _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
 110 
 111   _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
 112   _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
 113 
 114   if (UseStringDeduplication) {
 115     _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):");
 116     _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):");
 117   } else {
 118     _gc_par_phases[StringDedupQueueFixup] = NULL;
 119     _gc_par_phases[StringDedupTableFixup] = NULL;
 120   }
 121 
 122   _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):");
 123   _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:");
 124   _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
 125 
 126   _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Young Free Collection Set (ms):");
 127   _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>(max_gc_threads, "Non-Young Free Collection Set (ms):");
 128 
 129   reset();
 130 }
 131 
 132 void G1GCPhaseTimes::reset() {
 133   _cur_collection_par_time_ms = 0.0;
 134   _cur_optional_evac_ms = 0.0;
 135   _cur_collection_code_root_fixup_time_ms = 0.0;
 136   _cur_strong_code_root_purge_time_ms = 0.0;
 137   _cur_evac_fail_recalc_used = 0.0;
 138   _cur_evac_fail_remove_self_forwards = 0.0;
 139   _cur_string_dedup_fixup_time_ms = 0.0;
 140   _cur_prepare_tlab_time_ms = 0.0;
 141   _cur_resize_tlab_time_ms = 0.0;
 142   _cur_derived_pointer_table_update_time_ms = 0.0;
 143   _cur_clear_ct_time_ms = 0.0;
 144   _cur_expand_heap_time_ms = 0.0;
 145   _cur_ref_proc_time_ms = 0.0;
 146   _cur_collection_start_sec = 0.0;
 147   _root_region_scan_wait_time_ms = 0.0;
 148   _external_accounted_time_ms = 0.0;
 149   _recorded_clear_claimed_marks_time_ms = 0.0;
 150   _recorded_young_cset_choice_time_ms = 0.0;
 151   _recorded_non_young_cset_choice_time_ms = 0.0;
 152   _recorded_redirty_logged_cards_time_ms = 0.0;
 153   _recorded_preserve_cm_referents_time_ms = 0.0;
 154   _recorded_merge_pss_time_ms = 0.0;


 222       ASSERT_PHASE_UNINITIALIZED(ScanRS);
 223       ASSERT_PHASE_UNINITIALIZED(CodeRoots);
 224       ASSERT_PHASE_UNINITIALIZED(ObjCopy);
 225       ASSERT_PHASE_UNINITIALIZED(Termination);
 226     }
 227   }
 228 }
 229 
 230 #undef ASSERT_PHASE_UNINITIALIZED
 231 
 232 // record the time a phase took in seconds
 233 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
 234   _gc_par_phases[phase]->set(worker_i, secs);
 235 }
 236 
 237 // add a number of seconds to a phase
 238 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 239   _gc_par_phases[phase]->add(worker_i, secs);
 240 }
 241 
 242 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_i, double secs) {
 243   if (_gc_par_phases[phase]->get(worker_i) == _gc_par_phases[phase]->uninitialized()) {
 244     record_time_secs(phase, worker_i, secs);
 245   } else {
 246     add_time_secs(phase, worker_i, secs);
 247   }
 248 }
 249 
 250 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count, uint index) {
 251   _gc_par_phases[phase]->set_thread_work_item(worker_i, count, index);
 252 }
 253 
 254 // return the average time for a phase in milliseconds
 255 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
 256   return _gc_par_phases[phase]->average() * 1000.0;
 257 }
 258 
 259 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
 260   assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
 261   return _gc_par_phases[phase]->thread_work_items(index)->sum();
 262 }
 263 
 264 template <class T>
 265 void G1GCPhaseTimes::details(T* phase, const char* indent) const {
 266   LogTarget(Trace, gc, phases, task) lt;


 343 
 344   info_time("Pre Evacuate Collection Set", sum_ms);
 345 
 346   if (_root_region_scan_wait_time_ms > 0.0) {
 347     debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
 348   }
 349   debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
 350   debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
 351   if (G1EagerReclaimHumongousObjects) {
 352     debug_time("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
 353     trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
 354     trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
 355   }
 356 
 357   if (_recorded_clear_claimed_marks_time_ms > 0.0) {
 358     debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
 359   }
 360   return sum_ms;
 361 }
 362 
 363 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
 364   const double sum_ms = _cur_optional_evac_ms;
 365   if (sum_ms > 0) {
 366     info_time("Evacuate Optional Collection Set", sum_ms);
 367     debug_phase(_gc_par_phases[OptScanRS]);
 368     debug_phase(_gc_par_phases[OptObjCopy]);
 369   }
 370   return sum_ms;
 371 }
 372 
 373 double G1GCPhaseTimes::print_evacuate_collection_set() const {
 374   const double sum_ms = _cur_collection_par_time_ms;
 375 
 376   info_time("Evacuate Collection Set", sum_ms);
 377 
 378   trace_phase(_gc_par_phases[GCWorkerStart], false);
 379   debug_phase(_gc_par_phases[ExtRootScan]);
 380   for (int i = ThreadRoots; i <= SATBFiltering; i++) {
 381     trace_phase(_gc_par_phases[i]);
 382   }
 383   debug_phase(_gc_par_phases[UpdateRS]);
 384   if (G1HotCardCache::default_use_cache()) {
 385     trace_phase(_gc_par_phases[ScanHCC]);
 386   }
 387   debug_phase(_gc_par_phases[ScanRS]);
 388   debug_phase(_gc_par_phases[CodeRoots]);
 389 #if INCLUDE_AOT
 390   debug_phase(_gc_par_phases[AOTCodeRoots]);
 391 #endif
 392   debug_phase(_gc_par_phases[ObjCopy]);


 462   debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
 463 
 464 
 465   return sum_ms;
 466 }
 467 
 468 void G1GCPhaseTimes::print_other(double accounted_ms) const {
 469   info_time("Other", _gc_pause_time_ms - accounted_ms);
 470 }
 471 
 472 void G1GCPhaseTimes::print() {
 473   note_gc_end();
 474 
 475   if (_cur_verify_before_time_ms > 0.0) {
 476     debug_time("Verify Before", _cur_verify_before_time_ms);
 477   }
 478 
 479   double accounted_ms = 0.0;
 480   accounted_ms += print_pre_evacuate_collection_set();
 481   accounted_ms += print_evacuate_collection_set();
 482   accounted_ms += print_evacuate_optional_collection_set();
 483   accounted_ms += print_post_evacuate_collection_set();
 484   print_other(accounted_ms);
 485 
 486   if (_cur_verify_after_time_ms > 0.0) {
 487     debug_time("Verify After", _cur_verify_after_time_ms);
 488   }
 489 }
 490 
 491 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
 492   static const char* names[] = {
 493       "GCWorkerStart",
 494       "ExtRootScan",
 495       "ThreadRoots",
 496       "StringTableRoots",
 497       "UniverseRoots",
 498       "JNIRoots",
 499       "ObjectSynchronizerRoots",
 500       "ManagementRoots",
 501       "SystemDictionaryRoots",
 502       "CLDGRoots",
 503       "JVMTIRoots",
 504       "CMRefRoots",
 505       "WaitForStrongCLD",
 506       "WeakCLDRoots",
 507       "SATBFiltering",
 508       "UpdateRS",
 509       "ScanHCC",
 510       "ScanRS",
 511       "OptScanRS",
 512       "CodeRoots",
 513 #if INCLUDE_AOT
 514       "AOTCodeRoots",
 515 #endif
 516       "ObjCopy",
 517       "OptObjCopy",
 518       "Termination",
 519       "Other",
 520       "GCWorkerTotal",
 521       "GCWorkerEnd",
 522       "StringDedupQueueFixup",
 523       "StringDedupTableFixup",
 524       "RedirtyCards",
 525       "YoungFreeCSet",
 526       "NonYoungFreeCSet"
 527       //GCParPhasesSentinel only used to tell end of enum
 528       };
 529 
 530   STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
 531 
 532   return names[phase];
 533 }
 534 
 535 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
 536   _pss(pss),
 537   _start(Ticks::now()),


 569     _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
 570   }
 571 }
 572 
 573 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
 574                                                  G1ParScanThreadState* pss,
 575                                                  G1GCPhaseTimes::GCParPhases phase,
 576                                                  uint worker_id) :
 577   G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
 578   _total_time(),
 579   _trim_time(),
 580   _trim_tracker(pss, _total_time, _trim_time) {
 581 }
 582 
 583 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
 584   if (_phase_times != NULL) {
 585     // Explicitly stop the trim tracker since it's not yet destructed.
 586     _trim_tracker.stop();
 587     // Exclude trim time by increasing the start time.
 588     _start_time += _trim_time;
 589     _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds());
 590   }
 591 }
 592 
< prev index next >