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

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

*** 25,48 ****
  #include "precompiled.hpp"
  #include "gc/g1/g1CollectedHeap.inline.hpp"
  #include "gc/g1/g1GCPhaseTimes.hpp"
  #include "gc/g1/g1HotCardCache.hpp"
  #include "gc/g1/g1StringDedup.hpp"
! #include "gc/g1/workerDataArray.inline.hpp"
  #include "memory/resourceArea.hpp"
  #include "logging/log.hpp"
  #include "logging/logStream.hpp"
  #include "runtime/timer.hpp"
  #include "runtime/os.hpp"
  #include "utilities/macros.hpp"
  
  static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
  
! G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
    _max_gc_threads(max_gc_threads),
    _gc_start_counter(0),
!   _gc_pause_time_ms(0.0)
  {
    assert(max_gc_threads > 0, "Must have some GC threads");
  
    _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
    _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
--- 25,49 ----
  #include "precompiled.hpp"
  #include "gc/g1/g1CollectedHeap.inline.hpp"
  #include "gc/g1/g1GCPhaseTimes.hpp"
  #include "gc/g1/g1HotCardCache.hpp"
  #include "gc/g1/g1StringDedup.hpp"
! #include "gc/shared/workerDataArray.inline.hpp"
  #include "memory/resourceArea.hpp"
  #include "logging/log.hpp"
  #include "logging/logStream.hpp"
  #include "runtime/timer.hpp"
  #include "runtime/os.hpp"
  #include "utilities/macros.hpp"
  
  static const char* Indents[5] = {"", "  ", "    ", "      ", "        "};
  
! G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
    _max_gc_threads(max_gc_threads),
    _gc_start_counter(0),
!   _gc_pause_time_ms(0.0),
!   _ref_phase_times((GCTimer*)gc_timer, max_gc_threads)
  {
    assert(max_gc_threads > 0, "Must have some GC threads");
  
    _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):");
    _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):");
*** 150,159 ****
--- 151,162 ----
    for (int i = 0; i < GCParPhasesSentinel; i++) {
      if (_gc_par_phases[i] != NULL) {
        _gc_par_phases[i]->reset();
      }
    }
+ 
+   _ref_phase_times.reset();
  }
  
  void G1GCPhaseTimes::note_gc_start() {
    _gc_start_counter = os::elapsed_counter();
    reset();
*** 282,291 ****
--- 285,307 ----
  
  void G1GCPhaseTimes::debug_time(const char* name, double value) const {
    log_debug(gc, phases)("%s%s: " TIME_FORMAT, Indents[2], name, value);
  }
  
+ void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
+   LogTarget(Debug, gc, phases) lt;
+   LogTarget(Debug, gc, phases, ref) lt2;
+ 
+   if (lt.is_enabled()) {
+     LogStream ls(lt);
+     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
+   } else if (lt2.is_enabled()) {
+     LogStream ls(lt2);
+     ls.print_cr("%s%s: " TIME_FORMAT, Indents[2], name, value);
+   }
+ }
+ 
  void G1GCPhaseTimes::trace_time(const char* name, double value) const {
    log_trace(gc, phases)("%s%s: " TIME_FORMAT, Indents[3], name, value);
  }
  
  void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
*** 368,378 ****
    debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
  
    debug_time("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);
    trace_phase(_gc_par_phases[PreserveCMReferents]);
  
!   debug_time("Reference Processing", _cur_ref_proc_time_ms);
  
    if (G1StringDedup::is_enabled()) {
      debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
      debug_phase(_gc_par_phases[StringDedupQueueFixup]);
      debug_phase(_gc_par_phases[StringDedupTableFixup]);
--- 384,395 ----
    debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
  
    debug_time("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms);
    trace_phase(_gc_par_phases[PreserveCMReferents]);
  
!   debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
!   _ref_phase_times.print_all_references(2, false);
  
    if (G1StringDedup::is_enabled()) {
      debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
      debug_phase(_gc_par_phases[StringDedupQueueFixup]);
      debug_phase(_gc_par_phases[StringDedupTableFixup]);
*** 384,394 ****
      debug_time("Evacuation Failure", evac_fail_handling);
      trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
      trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
    }
  
!   debug_time("Reference Enqueuing", _cur_ref_enq_time_ms);
  
    debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
    debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
  
    debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
--- 401,412 ----
      debug_time("Evacuation Failure", evac_fail_handling);
      trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
      trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
    }
  
!   debug_time_for_reference("Reference Enqueuing", _cur_ref_enq_time_ms);
!   _ref_phase_times.print_enqueue_phase(2, false);
  
    debug_time("Merge Per-Thread State", _recorded_merge_pss_time_ms);
    debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
  
    debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);