--- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp	Mon Jul 02 10:54:17 2012 -0400
+++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp	Wed Jul 11 22:47:38 2012 +0200
@@ -29,6 +29,7 @@
 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
 #include "gc_implementation/g1/g1CollectorPolicy.hpp"
 #include "gc_implementation/g1/g1ErgoVerbose.hpp"
+#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
 #include "gc_implementation/g1/g1Log.hpp"
 #include "gc_implementation/g1/heapRegionRemSet.hpp"
 #include "gc_implementation/shared/gcPolicyCounters.hpp"
@@ -77,57 +78,6 @@
   1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30
 };
 
-// Help class for avoiding interleaved logging
-class LineBuffer: public StackObj {
-
-private:
-  static const int BUFFER_LEN = 1024;
-  static const int INDENT_CHARS = 3;
-  char _buffer[BUFFER_LEN];
-  int _indent_level;
-  int _cur;
-
-  void vappend(const char* format, va_list ap) {
-    int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
-    if (res != -1) {
-      _cur += res;
-    } else {
-      DEBUG_ONLY(warning("buffer too small in LineBuffer");)
-      _buffer[BUFFER_LEN -1] = 0;
-      _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
-    }
-  }
-
-public:
-  explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
-    for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
-      _buffer[_cur] = ' ';
-    }
-  }
-
-#ifndef PRODUCT
-  ~LineBuffer() {
-    assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
-  }
-#endif
-
-  void append(const char* format, ...) {
-    va_list ap;
-    va_start(ap, format);
-    vappend(format, ap);
-    va_end(ap);
-  }
-
-  void append_and_print_cr(const char* format, ...) {
-    va_list ap;
-    va_start(ap, format);
-    vappend(format, ap);
-    va_end(ap);
-    gclog_or_tty->print_cr("%s", _buffer);
-    _cur = _indent_level * INDENT_CHARS;
-  }
-};
-
 G1CollectorPolicy::G1CollectorPolicy() :
   _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
                         ? ParallelGCThreads : 1),
@@ -135,20 +85,6 @@
   _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
   _stop_world_start(0.0),
 
-  _cur_clear_ct_time_ms(0.0),
-  _root_region_scan_wait_time_ms(0.0),
-
-  _cur_ref_proc_time_ms(0.0),
-  _cur_ref_enq_time_ms(0.0),
-
-#ifndef PRODUCT
-  _min_clear_cc_time_ms(-1.0),
-  _max_clear_cc_time_ms(-1.0),
-  _cur_clear_cc_time_ms(0.0),
-  _cum_clear_cc_time_ms(0.0),
-  _num_cc_clears(0L),
-#endif
-
   _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
   _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
 
@@ -257,30 +193,9 @@
   _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime());
   _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0;
 
-  _par_last_gc_worker_start_times_ms = new double[_parallel_gc_threads];
-  _par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads];
-  _par_last_satb_filtering_times_ms = new double[_parallel_gc_threads];
-
-  _par_last_update_rs_times_ms = new double[_parallel_gc_threads];
-  _par_last_update_rs_processed_buffers = new double[_parallel_gc_threads];
-
-  _par_last_scan_rs_times_ms = new double[_parallel_gc_threads];
-
-  _par_last_obj_copy_times_ms = new double[_parallel_gc_threads];
+  _phase_times = new G1GCPhaseTimes(_parallel_gc_threads);
 
-  _par_last_termination_times_ms = new double[_parallel_gc_threads];
-  _par_last_termination_attempts = new double[_parallel_gc_threads];
-  _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads];
-  _par_last_gc_worker_times_ms = new double[_parallel_gc_threads];
-  _par_last_gc_worker_other_times_ms = new double[_parallel_gc_threads];
-
-  int index;
-  if (ParallelGCThreads == 0)
-    index = 0;
-  else if (ParallelGCThreads > 8)
-    index = 7;
-  else
-    index = ParallelGCThreads - 1;
+  int index = MIN2(_parallel_gc_threads - 1, 7);
 
   _pending_card_diff_seq->add(0.0);
   _rs_length_diff_seq->add(rs_length_diff_defaults[index]);
@@ -824,7 +739,7 @@
 #endif // PRODUCT
 
 void G1CollectorPolicy::record_full_collection_start() {
-  _cur_collection_start_sec = os::elapsedTime();
+  _full_collection_start_sec = os::elapsedTime();
   // Release the future to-space so that it is available for compaction into.
   _g1->set_full_collection();
 }
@@ -833,7 +748,7 @@
   // Consider this like a collection pause for the purposes of allocation
   // since last pause.
   double end_sec = os::elapsedTime();
-  double full_gc_time_sec = end_sec - _cur_collection_start_sec;
+  double full_gc_time_sec = end_sec - _full_collection_start_sec;
   double full_gc_time_ms = full_gc_time_sec * 1000.0;
 
   _trace_gen1_time_data.record_full_collection(full_gc_time_ms);
@@ -869,12 +784,6 @@
 
 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
                                                       size_t start_used) {
-  if (G1Log::finer()) {
-    gclog_or_tty->stamp(PrintGCTimeStamps);
-    gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause())
-      .append(gcs_are_young() ? " (young)" : " (mixed)"));
-  }
-
   // We only need to do this here as the policy will only be applied
   // to the GC we're about to start. so, no point is calculating this
   // every time we calculate / recalculate the target young length.
@@ -888,7 +797,7 @@
   _trace_gen0_time_data.record_start_collection(s_w_t_ms);
   _stop_world_start = 0.0;
 
-  _cur_collection_start_sec = start_time_sec;
+  phase_times()->_cur_collection_start_sec = start_time_sec;
   _cur_collection_pause_used_at_start_bytes = start_used;
   _cur_collection_pause_used_regions_at_start = _g1->used_regions();
   _pending_cards = _g1->pending_card_num();
@@ -902,30 +811,6 @@
   _survivor_bytes_before_gc = young_list->survivor_used_bytes();
   _capacity_before_gc = _g1->capacity();
 
-#ifdef DEBUG
-  // initialise these to something well known so that we can spot
-  // if they are not set properly
-
-  for (int i = 0; i < _parallel_gc_threads; ++i) {
-    _par_last_gc_worker_start_times_ms[i] = -1234.0;
-    _par_last_ext_root_scan_times_ms[i] = -1234.0;
-    _par_last_satb_filtering_times_ms[i] = -1234.0;
-    _par_last_update_rs_times_ms[i] = -1234.0;
-    _par_last_update_rs_processed_buffers[i] = -1234.0;
-    _par_last_scan_rs_times_ms[i] = -1234.0;
-    _par_last_obj_copy_times_ms[i] = -1234.0;
-    _par_last_termination_times_ms[i] = -1234.0;
-    _par_last_termination_attempts[i] = -1234.0;
-    _par_last_gc_worker_end_times_ms[i] = -1234.0;
-    _par_last_gc_worker_times_ms[i] = -1234.0;
-    _par_last_gc_worker_other_times_ms[i] = -1234.0;
-  }
-#endif
-
-  // This is initialized to zero here and is set during the evacuation
-  // pause if we actually waited for the root region scanning to finish.
-  _root_region_scan_wait_time_ms = 0.0;
-
   _last_gc_was_young = false;
 
   // do that for any other surv rate groups
@@ -974,127 +859,6 @@
   }
 }
 
-void G1CollectorPolicy::record_concurrent_pause_end() {
-}
-
-template<class T>
-T sum_of(T* sum_arr, int start, int n, int N) {
-  T sum = (T)0;
-  for (int i = 0; i < n; i++) {
-    int j = (start + i) % N;
-    sum += sum_arr[j];
-  }
-  return sum;
-}
-
-void G1CollectorPolicy::print_par_stats(int level,
-                                        const char* str,
-                                        double* data,
-                                        bool showDecimals) {
-  double min = data[0], max = data[0];
-  double total = 0.0;
-  LineBuffer buf(level);
-  buf.append("[%s (ms):", str);
-  for (uint i = 0; i < no_of_gc_threads(); ++i) {
-    double val = data[i];
-    if (val < min)
-      min = val;
-    if (val > max)
-      max = val;
-    total += val;
-    if (G1Log::finest()) {
-      if (showDecimals) {
-        buf.append("  %.1lf", val);
-      } else {
-        buf.append("  %d", (int)val);
-      }
-    }
-  }
-
-  if (G1Log::finest()) {
-    buf.append_and_print_cr("");
-  }
-  double avg = total / (double) no_of_gc_threads();
-  if (showDecimals) {
-    buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]",
-      min, avg, max, max - min, total);
-  } else {
-    buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]",
-      (int)min, (int)avg, (int)max, (int)max - (int)min, (int)total);
-  }
-}
-
-void G1CollectorPolicy::print_stats(int level,
-                                    const char* str,
-                                    double value) {
-  LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
-}
-
-void G1CollectorPolicy::print_stats(int level,
-                                    const char* str,
-                                    double value,
-                                    int workers) {
-  LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
-}
-
-void G1CollectorPolicy::print_stats(int level,
-                                    const char* str,
-                                    int value) {
-  LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
-}
-
-double G1CollectorPolicy::avg_value(double* data) {
-  if (G1CollectedHeap::use_parallel_gc_threads()) {
-    double ret = 0.0;
-    for (uint i = 0; i < no_of_gc_threads(); ++i) {
-      ret += data[i];
-    }
-    return ret / (double) no_of_gc_threads();
-  } else {
-    return data[0];
-  }
-}
-
-double G1CollectorPolicy::max_value(double* data) {
-  if (G1CollectedHeap::use_parallel_gc_threads()) {
-    double ret = data[0];
-    for (uint i = 1; i < no_of_gc_threads(); ++i) {
-      if (data[i] > ret) {
-        ret = data[i];
-      }
-    }
-    return ret;
-  } else {
-    return data[0];
-  }
-}
-
-double G1CollectorPolicy::sum_of_values(double* data) {
-  if (G1CollectedHeap::use_parallel_gc_threads()) {
-    double sum = 0.0;
-    for (uint i = 0; i < no_of_gc_threads(); i++) {
-      sum += data[i];
-    }
-    return sum;
-  } else {
-    return data[0];
-  }
-}
-
-double G1CollectorPolicy::max_sum(double* data1, double* data2) {
-  double ret = data1[0] + data2[0];
-
-  if (G1CollectedHeap::use_parallel_gc_threads()) {
-    for (uint i = 1; i < no_of_gc_threads(); ++i) {
-      double data = data1[i] + data2[i];
-      if (data > ret) {
-        ret = data;
-      }
-    }
-  }
-  return ret;
-}
-
 bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) {
   if (_g1->concurrent_mark()->cmThread()->during_cycle()) {
     return false;
@@ -1142,10 +906,8 @@
 // Anything below that is considered to be zero
 #define MIN_TIMER_GRANULARITY 0.0000001
 
-void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
+void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
   double end_time_sec = os::elapsedTime();
-  double elapsed_ms = _last_pause_time_ms;
-  bool parallel = G1CollectedHeap::use_parallel_gc_threads();
   assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(),
          "otherwise, the subtraction below does not make sense");
   size_t rs_size =
@@ -1154,7 +916,6 @@
   assert(cur_used_bytes == _g1->recalculate_used(), "It should!");
   bool last_pause_included_initial_mark = false;
   bool update_stats = !_g1->evacuation_failed();
-  set_no_of_gc_threads(no_of_gc_threads);
 
 #ifndef PRODUCT
   if (G1YoungSurvRateVerbose) {
@@ -1174,7 +935,7 @@
     set_initiate_conc_mark_if_possible();
   }
 
-  _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
+  _mmu_tracker->add_pause(end_time_sec - pause_time_ms/1000.0,
                           end_time_sec, false);
 
   size_t freed_bytes =
@@ -1185,58 +946,11 @@
     (double)surviving_bytes/
     (double)_collection_set_bytes_used_before;
 
-  // These values are used to update the summary information that is
-  // displayed when TraceGen0Time is enabled, and are output as part
-  // of the "finer" output, in the non-parallel case.
-
-  double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
-  double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
-  double update_rs_time = avg_value(_par_last_update_rs_times_ms);
-  double update_rs_processed_buffers =
-    sum_of_values(_par_last_update_rs_processed_buffers);
-  double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
-  double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
-  double termination_time = avg_value(_par_last_termination_times_ms);
-
-  double known_time = ext_root_scan_time +
-                      satb_filtering_time +
-                      update_rs_time +
-                      scan_rs_time +
-                      obj_copy_time;
-
-  double other_time_ms = elapsed_ms;
-
-  // Subtract the root region scanning wait time. It's initialized to
-  // zero at the start of the pause.
-  other_time_ms -= _root_region_scan_wait_time_ms;
-
-  if (parallel) {
-    other_time_ms -= _cur_collection_par_time_ms;
-  } else {
-    other_time_ms -= known_time;
-  }
-
-  // Now subtract the time taken to fix up roots in generated code
-  other_time_ms -= _cur_collection_code_root_fixup_time_ms;
-
-  // Subtract the time taken to clean the card table from the
-  // current value of "other time"
-  other_time_ms -= _cur_clear_ct_time_ms;
-
-  // TraceGen0Time and TraceGen1Time summary info updating.
-
   if (update_stats) {
-    double parallel_known_time = known_time + termination_time;
-    double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
-
-    _trace_gen0_time_data.record_end_collection(
-      elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms,
-      ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time,
-      termination_time, parallel_other_time, _cur_clear_ct_time_ms);
-
+    _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
     // this is where we update the allocation rate of the application
     double app_time_ms =
-      (_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
+      (phase_times()->_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
     if (app_time_ms < MIN_TIMER_GRANULARITY) {
       // This usually happens due to the timer not having the required
       // granularity. Some Linuxes are the usual culprits.
@@ -1257,7 +971,7 @@
 
     double interval_ms =
       (end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0;
-    update_recent_gc_times(end_time_sec, elapsed_ms);
+    update_recent_gc_times(end_time_sec, pause_time_ms);
     _recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms;
     if (recent_avg_pause_time_ratio() < 0.0 ||
         (recent_avg_pause_time_ratio() - 1.0 > 0.0)) {
@@ -1284,90 +998,6 @@
       }
     }
   }
-
-  if (G1Log::finer()) {
-    bool print_marking_info =
-      _g1->mark_in_progress() && !last_pause_included_initial_mark;
-
-    gclog_or_tty->print_cr("%s, %1.8lf secs]",
-                           (last_pause_included_initial_mark) ? " (initial-mark)" : "",
-                           elapsed_ms / 1000.0);
-
-    if (_root_region_scan_wait_time_ms > 0.0) {
-      print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
-    }
-    if (parallel) {
-      print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_gc_threads);
-      print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
-      print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
-      if (print_marking_info) {
-        print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
-      }
-      print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
-      if (G1Log::finest()) {
-        print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers,
-          false /* showDecimals */);
-      }
-      print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
-      print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
-      print_par_stats(2, "Termination", _par_last_termination_times_ms);
-      if (G1Log::finest()) {
-        print_par_stats(3, "Termination Attempts", _par_last_termination_attempts,
-          false /* showDecimals */);
-      }
-
-      for (int i = 0; i < _parallel_gc_threads; i++) {
-        _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
-                                          _par_last_gc_worker_start_times_ms[i];
-
-        double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
-                                   _par_last_satb_filtering_times_ms[i] +
-                                   _par_last_update_rs_times_ms[i] +
-                                   _par_last_scan_rs_times_ms[i] +
-                                   _par_last_obj_copy_times_ms[i] +
-                                   _par_last_termination_times_ms[i];
-
-        _par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] -
-                                                worker_known_time;
-      }
-
-      print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
-      print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms);
-      print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
-    } else {
-      print_stats(1, "Ext Root Scanning", ext_root_scan_time);
-      if (print_marking_info) {
-        print_stats(1, "SATB Filtering", satb_filtering_time);
-      }
-      print_stats(1, "Update RS", update_rs_time);
-      if (G1Log::finest()) {
-        print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers);
-      }
-      print_stats(1, "Scan RS", scan_rs_time);
-      print_stats(1, "Object Copying", obj_copy_time);
-    }
-    print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
-    print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
-#ifndef PRODUCT
-    print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
-    print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
-    print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
-    print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
-    if (_num_cc_clears > 0) {
-      print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
-    }
-#endif
-    print_stats(1, "Other", other_time_ms);
-    print_stats(2, "Choose CSet",
-                   (_recorded_young_cset_choice_time_ms +
-                    _recorded_non_young_cset_choice_time_ms));
-    print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
-    print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
-    print_stats(2, "Free CSet",
-                   (_recorded_young_free_cset_time_ms +
-                    _recorded_non_young_free_cset_time_ms));
-  }
-
   bool new_in_marking_window = _in_marking_window;
   bool new_in_marking_window_im = false;
   if (during_initial_mark_pause()) {
@@ -1406,8 +1036,6 @@
   // do that for any other surv rate groupsx
 
   if (update_stats) {
-    double pause_time_ms = elapsed_ms;
-
     size_t diff = 0;
     if (_max_pending_cards >= _pending_cards) {
       diff = _max_pending_cards - _pending_cards;
@@ -1416,7 +1044,7 @@
 
     double cost_per_card_ms = 0.0;
     if (_pending_cards > 0) {
-      cost_per_card_ms = update_rs_time / (double) _pending_cards;
+      cost_per_card_ms = phase_times()->_update_rs_time / (double) _pending_cards;
       _cost_per_card_ms_seq->add(cost_per_card_ms);
     }
 
@@ -1424,7 +1052,7 @@
 
     double cost_per_entry_ms = 0.0;
     if (cards_scanned > 10) {
-      cost_per_entry_ms = scan_rs_time / (double) cards_scanned;
+      cost_per_entry_ms = phase_times()->_scan_rs_time / (double) cards_scanned;
       if (_last_gc_was_young) {
         _cost_per_entry_ms_seq->add(cost_per_entry_ms);
       } else {
@@ -1464,7 +1092,7 @@
     size_t copied_bytes = surviving_bytes;
     double cost_per_byte_ms = 0.0;
     if (copied_bytes > 0) {
-      cost_per_byte_ms = obj_copy_time / (double) copied_bytes;
+      cost_per_byte_ms = phase_times()->_obj_copy_time / (double) copied_bytes;
       if (_in_marking_window) {
         _cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms);
       } else {
@@ -1473,21 +1101,21 @@
     }
 
     double all_other_time_ms = pause_time_ms -
-      (update_rs_time + scan_rs_time + obj_copy_time + termination_time);
+      (phase_times()->_update_rs_time + phase_times()->_scan_rs_time + phase_times()->_obj_copy_time + phase_times()->_termination_time);
 
     double young_other_time_ms = 0.0;
     if (young_cset_region_length() > 0) {
       young_other_time_ms =
-        _recorded_young_cset_choice_time_ms +
-        _recorded_young_free_cset_time_ms;
+        phase_times()->_recorded_young_cset_choice_time_ms +
+        phase_times()->_recorded_young_free_cset_time_ms;
       _young_other_cost_per_region_ms_seq->add(young_other_time_ms /
                                           (double) young_cset_region_length());
     }
     double non_young_other_time_ms = 0.0;
     if (old_cset_region_length() > 0) {
       non_young_other_time_ms =
-        _recorded_non_young_cset_choice_time_ms +
-        _recorded_non_young_free_cset_time_ms;
+        phase_times()->_recorded_non_young_cset_choice_time_ms +
+        phase_times()->_recorded_non_young_free_cset_time_ms;
 
       _non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms /
                                             (double) old_cset_region_length());
@@ -1514,7 +1142,7 @@
 
   // Note that _mmu_tracker->max_gc_time() returns the time in seconds.
   double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0;
-  adjust_concurrent_refinement(update_rs_time, update_rs_processed_buffers, update_rs_time_goal_ms);
+  adjust_concurrent_refinement(phase_times()->_update_rs_time, phase_times()->_update_rs_processed_buffers, update_rs_time_goal_ms);
 
   _collectionSetChooser->verify();
 }
@@ -2323,7 +1951,7 @@
   set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
 
   double young_end_time_sec = os::elapsedTime();
-  _recorded_young_cset_choice_time_ms =
+  phase_times()->_recorded_young_cset_choice_time_ms =
     (young_end_time_sec - young_start_time_sec) * 1000.0;
 
   // We are doing young collections so reset this.
@@ -2439,7 +2067,7 @@
                 predicted_pause_time_ms, target_pause_time_ms);
 
   double non_young_end_time_sec = os::elapsedTime();
-  _recorded_non_young_cset_choice_time_ms =
+  phase_times()->_recorded_non_young_cset_choice_time_ms =
     (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
 }
 
@@ -2455,33 +2083,29 @@
   }
 }
 
-void TraceGen0TimeData::record_end_collection(
-     double total_ms,
-     double other_ms,
-     double root_region_scan_wait_ms,
-     double parallel_ms,
-     double ext_root_scan_ms,
-     double satb_filtering_ms,
-     double update_rs_ms,
-     double scan_rs_ms,
-     double obj_copy_ms,
-     double termination_ms,
-     double parallel_other_ms,
-     double clear_ct_ms)
-{
+void TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times) {
   if(TraceGen0Time) {
-    _total.add(total_ms);
-    _other.add(other_ms);
-    _root_region_scan_wait.add(root_region_scan_wait_ms);
-    _parallel.add(parallel_ms);
-    _ext_root_scan.add(ext_root_scan_ms);
-    _satb_filtering.add(satb_filtering_ms);
-    _update_rs.add(update_rs_ms);
-    _scan_rs.add(scan_rs_ms);
-    _obj_copy.add(obj_copy_ms);
-    _termination.add(termination_ms);
-    _parallel_other.add(parallel_other_ms);
-    _clear_ct.add(clear_ct_ms);
+    _total.add(pause_time_ms);
+    _other.add(pause_time_ms - phase_times->accounted_time_ms());
+    _root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms);
+    _parallel.add(phase_times->_cur_collection_par_time_ms);
+    _ext_root_scan.add(phase_times->_ext_root_scan_time);
+    _satb_filtering.add(phase_times->_satb_filtering_time);
+    _update_rs.add(phase_times->_update_rs_time);
+    _scan_rs.add(phase_times->_scan_rs_time);
+    _obj_copy.add(phase_times->_obj_copy_time);
+    _termination.add(phase_times->_termination_time);
+
+    double parallel_known_time = phase_times->_ext_root_scan_time +
+      phase_times->_satb_filtering_time +
+      phase_times->_update_rs_time +
+      phase_times->_scan_rs_time +
+      phase_times->_obj_copy_time +
+      + phase_times->_termination_time;
+
+    double parallel_other_time = phase_times->_cur_collection_par_time_ms - parallel_known_time;
+    _parallel_other.add(parallel_other_time);
+    _clear_ct.add(phase_times->_cur_clear_ct_time_ms);
   }
 }
 
@@ -2497,20 +2121,18 @@
   }
 }
 
-void TraceGen0TimeData::print_summary(int level,
-                                      const char* str,
+void TraceGen0TimeData::print_summary(const char* str,
                                       const NumberSeq* seq) const {
   double sum = seq->sum();
-  LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
+  gclog_or_tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)",
                 str, sum / 1000.0, seq->avg());
 }
 
-void TraceGen0TimeData::print_summary_sd(int level,
-                                         const char* str,
+void TraceGen0TimeData::print_summary_sd(const char* str,
                                          const NumberSeq* seq) const {
-  print_summary(level, str, seq);
-  LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
-                seq->num(), seq->sd(), seq->maximum());
+  print_summary(str, seq);
+  gclog_or_tty->print_cr("%+45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
+                "(num", seq->num(), seq->sd(), seq->maximum());
 }
 
 void TraceGen0TimeData::print() const {
@@ -2519,7 +2141,7 @@
   }
 
   gclog_or_tty->print_cr("ALL PAUSES");
-  print_summary_sd(0, "Total", &_total);
+  print_summary_sd("   Total", &_total);
   gclog_or_tty->print_cr("");
   gclog_or_tty->print_cr("");
   gclog_or_tty->print_cr("   Young GC Pauses: %8d", _young_pause_num);
@@ -2531,24 +2153,24 @@
   if (_young_pause_num == 0 && _mixed_pause_num == 0) {
     gclog_or_tty->print_cr("none");
   } else {
-    print_summary_sd(0, "Evacuation Pauses", &_total);
-    print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait);
-    print_summary(1, "Parallel Time", &_parallel);
-    print_summary(2, "Ext Root Scanning", &_ext_root_scan);
-    print_summary(2, "SATB Filtering", &_satb_filtering);
-    print_summary(2, "Update RS", &_update_rs);
-    print_summary(2, "Scan RS", &_scan_rs);
-    print_summary(2, "Object Copy", &_obj_copy);
-    print_summary(2, "Termination", &_termination);
-    print_summary(2, "Parallel Other", &_parallel_other);
-    print_summary(1, "Clear CT", &_clear_ct);
-    print_summary(1, "Other", &_other);
+    print_summary_sd("   Evacuation Pauses", &_total);
+    print_summary("      Root Region Scan Wait", &_root_region_scan_wait);
+    print_summary("      Parallel Time", &_parallel);
+    print_summary("         Ext Root Scanning", &_ext_root_scan);
+    print_summary("         SATB Filtering", &_satb_filtering);
+    print_summary("         Update RS", &_update_rs);
+    print_summary("         Scan RS", &_scan_rs);
+    print_summary("         Object Copy", &_obj_copy);
+    print_summary("         Termination", &_termination);
+    print_summary("         Parallel Other", &_parallel_other);
+    print_summary("      Clear CT", &_clear_ct);
+    print_summary("      Other", &_other);
   }
   gclog_or_tty->print_cr("");
 
   gclog_or_tty->print_cr("MISC");
-  print_summary_sd(0, "Stop World", &_all_stop_world_times_ms);
-  print_summary_sd(0, "Yields", &_all_yield_times_ms);
+  print_summary_sd("   Stop World", &_all_stop_world_times_ms);
+  print_summary_sd("   Yields", &_all_yield_times_ms);
 }
 
 void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {