< prev index next >

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

Print this page
rev 13328 : [mq]: webrev.0b
rev 13330 : imported patch webrev.2
rev 13331 : imported patch webrev.3b
rev 13332 : [mq]: webrev.4


  20  * or visit www.oracle.com if you need additional information or have any
  21  * questions.
  22  *
  23  */
  24 
  25 #include "precompiled.hpp"
  26 #include "gc/g1/g1CollectedHeap.inline.hpp"
  27 #include "gc/g1/g1GCPhaseTimes.hpp"
  28 #include "gc/g1/g1HotCardCache.hpp"
  29 #include "gc/g1/g1StringDedup.hpp"
  30 #include "gc/shared/workerDataArray.inline.hpp"
  31 #include "memory/resourceArea.hpp"
  32 #include "logging/log.hpp"
  33 #include "logging/logStream.hpp"
  34 #include "runtime/timer.hpp"
  35 #include "runtime/os.hpp"
  36 #include "utilities/macros.hpp"
  37 
  38 static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
  39 
  40 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
  41   _max_gc_threads(max_gc_threads),
  42   _gc_start_counter(0),
  43   _gc_pause_time_ms(0.0)

  44 {
  45   assert(max_gc_threads > 0, "Must have some GC threads");
  46 
  47   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
  48   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
  49 
  50   // Root scanning phases
  51   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
  52   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
  53   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  54   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  55   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  56   _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):");
  57   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  58   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  59   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  60   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  61   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  62   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
  63   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");


 135   _recorded_non_young_cset_choice_time_ms = 0.0;
 136   _recorded_redirty_logged_cards_time_ms = 0.0;
 137   _recorded_preserve_cm_referents_time_ms = 0.0;
 138   _recorded_merge_pss_time_ms = 0.0;
 139   _recorded_start_new_cset_time_ms = 0.0;
 140   _recorded_total_free_cset_time_ms = 0.0;
 141   _recorded_serial_free_cset_time_ms = 0.0;
 142   _cur_fast_reclaim_humongous_time_ms = 0.0;
 143   _cur_fast_reclaim_humongous_register_time_ms = 0.0;
 144   _cur_fast_reclaim_humongous_total = 0;
 145   _cur_fast_reclaim_humongous_candidates = 0;
 146   _cur_fast_reclaim_humongous_reclaimed = 0;
 147   _cur_verify_before_time_ms = 0.0;
 148   _cur_verify_after_time_ms = 0.0;
 149 
 150   for (int i = 0; i < GCParPhasesSentinel; i++) {
 151     if (_gc_par_phases[i] != NULL) {
 152       _gc_par_phases[i]->reset();
 153     }
 154   }


 155 }
 156 
 157 void G1GCPhaseTimes::note_gc_start() {
 158   _gc_start_counter = os::elapsed_counter();
 159   reset();
 160 }
 161 
 162 #define ASSERT_PHASE_UNINITIALIZED(phase) \
 163     assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 164 
 165 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
 166   double value = _gc_par_phases[phase]->get(worker);
 167   if (value != WorkerDataArray<double>::uninitialized()) {
 168     return value;
 169   }
 170   return 0.0;
 171 }
 172 
 173 void G1GCPhaseTimes::note_gc_end() {
 174   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);


 268 
 269 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
 270   LogTarget(Trace, gc, phases) lt;
 271   if (lt.is_enabled()) {
 272     LogStream ls(lt);
 273     log_phase(phase, 3, &ls, print_sum);
 274   }
 275 }
 276 
 277 #define TIME_FORMAT "%.1lfms"
 278 
 279 void G1GCPhaseTimes::info_time(const char* name, double value) const {
 280   log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
 281 }
 282 
 283 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
 284   log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
 285 }
 286 
 287 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
 288   Log(gc, phases) log;
 289   Log(gc, phases, ref) log2;
 290   if ((log.is_level(LogLevel::Debug) && !log2.is_level(LogLevel::Debug)) ||
 291       (log.is_level(LogLevel::Debug) && log2.is_level(LogLevel::Debug))) {
 292     log.debug_stream()->print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 293   } else if (!log.is_level(LogLevel::Debug) && log2.is_level(LogLevel::Debug)) {
 294     log2.debug_stream()->print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);


 295   }
 296 }
 297 
 298 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
 299   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
 300 }
 301 
 302 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 303   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
 304 }
 305 
 306 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 307   const double sum_ms = _root_region_scan_wait_time_ms +
 308                         _recorded_young_cset_choice_time_ms +
 309                         _recorded_non_young_cset_choice_time_ms +
 310                         _cur_fast_reclaim_humongous_register_time_ms +
 311                         _recorded_clear_claimed_marks_time_ms;
 312 
 313   info_time("Pre Evacuate Collection Set", sum_ms);
 314 


 365                         _recorded_preserve_cm_referents_time_ms +
 366                         _cur_ref_proc_time_ms +
 367                         _cur_ref_enq_time_ms +
 368                         _cur_clear_ct_time_ms +
 369                         _recorded_merge_pss_time_ms +
 370                         _cur_strong_code_root_purge_time_ms +
 371                         _recorded_redirty_logged_cards_time_ms +
 372                         _recorded_total_free_cset_time_ms +
 373                         _cur_fast_reclaim_humongous_time_ms +
 374                         _cur_expand_heap_time_ms +
 375                         _cur_string_dedup_fixup_time_ms;
 376 
 377   info_time("Post Evacuate Collection Set", sum_ms);
 378 
 379   debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
 380 
 381   debug_time("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);
 382   trace_phase(_gc_par_phases[PreserveCMReferents]);
 383 
 384   debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
 385   G1CollectedHeap::heap()->ref_phase_times()->print_all_references(2, false);
 386 
 387   if (G1StringDedup::is_enabled()) {
 388     debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
 389     debug_phase(_gc_par_phases[StringDedupQueueFixup]);
 390     debug_phase(_gc_par_phases[StringDedupTableFixup]);
 391   }
 392 
 393   debug_time("Clear Card Table", _cur_clear_ct_time_ms);
 394 
 395   if (G1CollectedHeap::heap()->evacuation_failed()) {
 396     debug_time("Evacuation Failure", evac_fail_handling);
 397     trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
 398     trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
 399   }
 400 
 401   debug_time_for_reference("Reference Enqueuing", _cur_ref_enq_time_ms);
 402   G1CollectedHeap::heap()->ref_phase_times()->print_enqueue_phase(2, false);
 403 
 404   debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
 405   debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
 406 
 407   debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 408   trace_phase(_gc_par_phases[RedirtyCards]);
 409 #if defined(COMPILER2) || INCLUDE_JVMCI
 410   debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
 411 #endif
 412 
 413   debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
 414   trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
 415   trace_phase(_gc_par_phases[YoungFreeCSet]);
 416   trace_phase(_gc_par_phases[NonYoungFreeCSet]);
 417 
 418   if (G1EagerReclaimHumongousObjects) {
 419     debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 420     trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
 421   }
 422   debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);




  20  * or visit www.oracle.com if you need additional information or have any
  21  * questions.
  22  *
  23  */
  24 
  25 #include "precompiled.hpp"
  26 #include "gc/g1/g1CollectedHeap.inline.hpp"
  27 #include "gc/g1/g1GCPhaseTimes.hpp"
  28 #include "gc/g1/g1HotCardCache.hpp"
  29 #include "gc/g1/g1StringDedup.hpp"
  30 #include "gc/shared/workerDataArray.inline.hpp"
  31 #include "memory/resourceArea.hpp"
  32 #include "logging/log.hpp"
  33 #include "logging/logStream.hpp"
  34 #include "runtime/timer.hpp"
  35 #include "runtime/os.hpp"
  36 #include "utilities/macros.hpp"
  37 
  38 static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
  39 
  40 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
  41   _max_gc_threads(max_gc_threads),
  42   _gc_start_counter(0),
  43   _gc_pause_time_ms(0.0),
  44   _ref_phase_times((GCTimer*)gc_timer, max_gc_threads)
  45 {
  46   assert(max_gc_threads > 0, "Must have some GC threads");
  47 
  48   _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
  49   _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
  50 
  51   // Root scanning phases
  52   _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):");
  53   _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):");
  54   _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):");
  55   _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):");
  56   _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):");
  57   _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):");
  58   _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):");
  59   _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):");
  60   _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):");
  61   _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):");
  62   _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):");
  63   _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):");
  64   _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):");


 136   _recorded_non_young_cset_choice_time_ms = 0.0;
 137   _recorded_redirty_logged_cards_time_ms = 0.0;
 138   _recorded_preserve_cm_referents_time_ms = 0.0;
 139   _recorded_merge_pss_time_ms = 0.0;
 140   _recorded_start_new_cset_time_ms = 0.0;
 141   _recorded_total_free_cset_time_ms = 0.0;
 142   _recorded_serial_free_cset_time_ms = 0.0;
 143   _cur_fast_reclaim_humongous_time_ms = 0.0;
 144   _cur_fast_reclaim_humongous_register_time_ms = 0.0;
 145   _cur_fast_reclaim_humongous_total = 0;
 146   _cur_fast_reclaim_humongous_candidates = 0;
 147   _cur_fast_reclaim_humongous_reclaimed = 0;
 148   _cur_verify_before_time_ms = 0.0;
 149   _cur_verify_after_time_ms = 0.0;
 150 
 151   for (int i = 0; i < GCParPhasesSentinel; i++) {
 152     if (_gc_par_phases[i] != NULL) {
 153       _gc_par_phases[i]->reset();
 154     }
 155   }
 156 
 157   _ref_phase_times.reset();
 158 }
 159 
 160 void G1GCPhaseTimes::note_gc_start() {
 161   _gc_start_counter = os::elapsed_counter();
 162   reset();
 163 }
 164 
 165 #define ASSERT_PHASE_UNINITIALIZED(phase) \
 166     assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
 167 
 168 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
 169   double value = _gc_par_phases[phase]->get(worker);
 170   if (value != WorkerDataArray<double>::uninitialized()) {
 171     return value;
 172   }
 173   return 0.0;
 174 }
 175 
 176 void G1GCPhaseTimes::note_gc_end() {
 177   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);


 271 
 272 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) const {
 273   LogTarget(Trace, gc, phases) lt;
 274   if (lt.is_enabled()) {
 275     LogStream ls(lt);
 276     log_phase(phase, 3, &ls, print_sum);
 277   }
 278 }
 279 
 280 #define TIME_FORMAT "%.1lfms"
 281 
 282 void G1GCPhaseTimes::info_time(const char* name, double value) const {
 283   log_info(gc, phases)("%s%s: " TIME_FORMAT, Indents[1], name, value);
 284 }
 285 
 286 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
 287   log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
 288 }
 289 
 290 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
 291   LogTarget(Debug, gc, phases) lt;
 292   LogTarget(Debug, gc, phases, ref) lt2;
 293 
 294   if (lt.is_enabled()) {
 295     LogStream ls(lt);
 296     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 297   } else if (lt2.is_enabled()) {
 298     LogStream ls(lt2);
 299     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
 300   }
 301 }
 302 
 303 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
 304   log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
 305 }
 306 
 307 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
 308   log_trace(gc, phases)("%s%s: " SIZE_FORMAT, Indents[3], name, value);
 309 }
 310 
 311 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
 312   const double sum_ms = _root_region_scan_wait_time_ms +
 313                         _recorded_young_cset_choice_time_ms +
 314                         _recorded_non_young_cset_choice_time_ms +
 315                         _cur_fast_reclaim_humongous_register_time_ms +
 316                         _recorded_clear_claimed_marks_time_ms;
 317 
 318   info_time("Pre Evacuate Collection Set", sum_ms);
 319 


 370                         _recorded_preserve_cm_referents_time_ms +
 371                         _cur_ref_proc_time_ms +
 372                         _cur_ref_enq_time_ms +
 373                         _cur_clear_ct_time_ms +
 374                         _recorded_merge_pss_time_ms +
 375                         _cur_strong_code_root_purge_time_ms +
 376                         _recorded_redirty_logged_cards_time_ms +
 377                         _recorded_total_free_cset_time_ms +
 378                         _cur_fast_reclaim_humongous_time_ms +
 379                         _cur_expand_heap_time_ms +
 380                         _cur_string_dedup_fixup_time_ms;
 381 
 382   info_time("Post Evacuate Collection Set", sum_ms);
 383 
 384   debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
 385 
 386   debug_time("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);
 387   trace_phase(_gc_par_phases[PreserveCMReferents]);
 388 
 389   debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
 390   _ref_phase_times.print_all_references(2, false);
 391 
 392   if (G1StringDedup::is_enabled()) {
 393     debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
 394     debug_phase(_gc_par_phases[StringDedupQueueFixup]);
 395     debug_phase(_gc_par_phases[StringDedupTableFixup]);
 396   }
 397 
 398   debug_time("Clear Card Table", _cur_clear_ct_time_ms);
 399 
 400   if (G1CollectedHeap::heap()->evacuation_failed()) {
 401     debug_time("Evacuation Failure", evac_fail_handling);
 402     trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
 403     trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
 404   }
 405 
 406   debug_time_for_reference("Reference Enqueuing", _cur_ref_enq_time_ms);
 407   _ref_phase_times.print_enqueue_phase(2, false);
 408 
 409   debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
 410   debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
 411 
 412   debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
 413   trace_phase(_gc_par_phases[RedirtyCards]);
 414 #if defined(COMPILER2) || INCLUDE_JVMCI
 415   debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
 416 #endif
 417 
 418   debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
 419   trace_time("Free Collection Set Serial", _recorded_serial_free_cset_time_ms);
 420   trace_phase(_gc_par_phases[YoungFreeCSet]);
 421   trace_phase(_gc_par_phases[NonYoungFreeCSet]);
 422 
 423   if (G1EagerReclaimHumongousObjects) {
 424     debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
 425     trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
 426   }
 427   debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);


< prev index next >