Mercurial > hg > icedtea9-forest > hotspot

changeset 3572:7553d441b878

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
Merge
author jmasa
date Tue, 17 Jul 2012 14:33:17 -0700
parents 0bca41b2fa63 (current diff) 3a431b605145 (diff)
children bc3e01899804
files
diffstat 8 files changed, 732 insertions(+), 663 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp	Tue Jul 17 12:32:26 2012 -0400
+++ b/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp	Tue Jul 17 14:33:17 2012 -0700
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -27,6 +27,7 @@
 #include "gc_implementation/g1/concurrentG1RefineThread.hpp"
 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
 #include "gc_implementation/g1/g1CollectorPolicy.hpp"
+#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
 #include "gc_implementation/g1/g1RemSet.hpp"
 #include "gc_implementation/g1/heapRegionSeq.inline.hpp"
 #include "memory/space.inline.hpp"
@@ -500,11 +501,11 @@
 }
 
 void ConcurrentG1Refine::clear_and_record_card_counts() {
-  if (G1ConcRSLogCacheSize == 0) return;
+  if (G1ConcRSLogCacheSize == 0) {
+    return;
+  }
 
-#ifndef PRODUCT
   double start = os::elapsedTime();
-#endif
 
   if (_expand_card_counts) {
     int new_idx = _cache_size_index + 1;
@@ -523,11 +524,8 @@
   assert((this_epoch+1) <= max_jint, "to many periods");
   // Update epoch
   _n_periods++;
-
-#ifndef PRODUCT
-  double elapsed = os::elapsedTime() - start;
-  _g1h->g1_policy()->record_cc_clear_time(elapsed * 1000.0);
-#endif
+  double cc_clear_time_ms = (os::elapsedTime() - start) * 1000;
+  _g1h->g1_policy()->phase_times()->record_cc_clear_time_ms(cc_clear_time_ms);
 }
 
 void ConcurrentG1Refine::print_worker_threads_on(outputStream* st) const {
--- a/src/share/vm/gc_implementation/g1/concurrentMark.cpp	Tue Jul 17 12:32:26 2012 -0400
+++ b/src/share/vm/gc_implementation/g1/concurrentMark.cpp	Tue Jul 17 14:33:17 2012 -0700
@@ -3156,9 +3156,6 @@
       _g1h->g1_policy()->record_concurrent_pause();
     }
     cmThread()->yield();
-    if (worker_id == 0) {
-      _g1h->g1_policy()->record_concurrent_pause_end();
-    }
     return true;
   } else {
     return false;
--- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp	Tue Jul 17 12:32:26 2012 -0400
+++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp	Tue Jul 17 14:33:17 2012 -0700
@@ -33,6 +33,7 @@
 #include "gc_implementation/g1/g1CollectorPolicy.hpp"
 #include "gc_implementation/g1/g1ErgoVerbose.hpp"
 #include "gc_implementation/g1/g1EvacFailure.hpp"
+#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
 #include "gc_implementation/g1/g1Log.hpp"
 #include "gc_implementation/g1/g1MarkSweep.hpp"
 #include "gc_implementation/g1/g1OopClosures.inline.hpp"
@@ -2274,7 +2275,7 @@
   while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) {
     n_completed_buffers++;
   }
-  g1_policy()->record_update_rs_processed_buffers(worker_i,
+  g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i,
                                                   (double) n_completed_buffers);
   dcqs.clear_n_completed_buffers();
   assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!");
@@ -3633,10 +3634,10 @@
     gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
     TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
 
-    GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause())
-      .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)")
-      .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : "");
-    TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty);
+    int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
+                                workers()->active_workers() : 1);
+    g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers,
+      g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause());
 
     TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
     TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
@@ -3699,9 +3700,15 @@
         // before the start GC event.
         _hr_printer.start_gc(false /* full */, (size_t) total_collections());
 
+        // This timing is only used by the ergonomics to handle our pause target.
+        // It is unclear why this should not include the full pause. We will
+        // investigate this in CR 7178365.
+        //
+        // Preserving the old comment here if that helps the investigation:
+        //
         // The elapsed time induced by the start time below deliberately elides
         // the possible verification above.
-        double start_time_sec = os::elapsedTime();
+        double sample_start_time_sec = os::elapsedTime();
         size_t start_used_bytes = used();
 
 #if YOUNG_LIST_VERBOSE
@@ -3710,7 +3717,7 @@
         g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty);
 #endif // YOUNG_LIST_VERBOSE
 
-        g1_policy()->record_collection_pause_start(start_time_sec,
+        g1_policy()->record_collection_pause_start(sample_start_time_sec,
                                                    start_used_bytes);
 
         double scan_wait_start = os::elapsedTime();
@@ -3719,11 +3726,12 @@
         // objects on them have been correctly scanned before we start
         // moving them during the GC.
         bool waited = _cm->root_regions()->wait_until_scan_finished();
+        double wait_time_ms = 0.0;
         if (waited) {
           double scan_wait_end = os::elapsedTime();
-          double wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0;
-          g1_policy()->record_root_region_scan_wait_time(wait_time_ms);
+          wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0;
         }
+        g1_policy()->phase_times()->record_root_region_scan_wait_time(wait_time_ms);
 
 #if YOUNG_LIST_VERBOSE
         gclog_or_tty->print_cr("\nAfter recording pause start.\nYoung_list:");
@@ -3877,12 +3885,16 @@
                                  true  /* verify_fingers */);
         _cm->note_end_of_gc();
 
-        double end_time_sec = os::elapsedTime();
-        double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS;
-        g1_policy()->record_pause_time_ms(pause_time_ms);
-        int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
-                                workers()->active_workers() : 1);
-        g1_policy()->record_collection_pause_end(active_workers);
+        // Collect thread local data to allow the ergonomics to use
+        // the collected information
+        g1_policy()->phase_times()->collapse_par_times();
+
+        // This timing is only used by the ergonomics to handle our pause target.
+        // It is unclear why this should not include the full pause. We will
+        // investigate this in CR 7178365.
+        double sample_end_time_sec = os::elapsedTime();
+        double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
+        g1_policy()->record_collection_pause_end(pause_time_ms);
 
         MemoryService::track_memory_usage();
 
@@ -3929,9 +3941,6 @@
       // RETIRE events are generated before the end GC event.
       _hr_printer.end_gc(false /* full */, (size_t) total_collections());
 
-      // We have to do this after we decide whether to expand the heap or not.
-      g1_policy()->print_heap_transition();
-
       if (mark_in_progress()) {
         concurrent_mark()->update_g1_committed();
       }
@@ -3941,13 +3950,14 @@
 #endif
 
       gc_epilogue(false);
+
+      g1_policy()->phase_times()->note_gc_end(os::elapsedTime());
+
+      // We have to do this after we decide whether to expand the heap or not.
+      g1_policy()->print_heap_transition();
     }
 
-    // The closing of the inner scope, immediately above, will complete
-    // logging at the "fine" level. The record_collection_pause_end() call
-    // above will complete logging at the "finer" level.
-    //
-    // It is not yet to safe, however, to tell the concurrent mark to
+    // It is not yet to safe to tell the concurrent mark to
     // start as we have some optional output below. We don't want the
     // output from the concurrent mark thread interfering with this
     // logging output either.
@@ -4695,7 +4705,7 @@
     if (worker_id >= _n_workers) return;  // no work needed this round
 
     double start_time_ms = os::elapsedTime() * 1000.0;
-    _g1h->g1_policy()->record_gc_worker_start_time(worker_id, start_time_ms);
+    _g1h->g1_policy()->phase_times()->record_gc_worker_start_time(worker_id, start_time_ms);
 
     {
       ResourceMark rm;
@@ -4744,8 +4754,8 @@
         evac.do_void();
         double elapsed_ms = (os::elapsedTime()-start)*1000.0;
         double term_ms = pss.term_time()*1000.0;
-        _g1h->g1_policy()->record_obj_copy_time(worker_id, elapsed_ms-term_ms);
-        _g1h->g1_policy()->record_termination(worker_id, term_ms, pss.term_attempts());
+        _g1h->g1_policy()->phase_times()->record_obj_copy_time(worker_id, elapsed_ms-term_ms);
+        _g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts());
       }
       _g1h->g1_policy()->record_thread_age_table(pss.age_table());
       _g1h->update_surviving_young_words(pss.surviving_young_words()+1);
@@ -4763,7 +4773,7 @@
     }
 
     double end_time_ms = os::elapsedTime() * 1000.0;
-    _g1h->g1_policy()->record_gc_worker_end_time(worker_id, end_time_ms);
+    _g1h->g1_policy()->phase_times()->record_gc_worker_end_time(worker_id, end_time_ms);
   }
 };
 
@@ -4874,15 +4884,15 @@
 
   double ext_roots_end = os::elapsedTime();
 
-  g1_policy()->reset_obj_copy_time(worker_i);
+  g1_policy()->phase_times()->reset_obj_copy_time(worker_i);
   double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() +
                                 buf_scan_non_heap_roots.closure_app_seconds();
-  g1_policy()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0);
+  g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0);
 
   double ext_root_time_ms =
     ((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0;
 
-  g1_policy()->record_ext_root_scan_time(worker_i, ext_root_time_ms);
+  g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms);
 
   // During conc marking we have to filter the per-thread SATB buffers
   // to make sure we remove any oops into the CSet (which will show up
@@ -4893,7 +4903,7 @@
     }
   }
   double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0;
-  g1_policy()->record_satb_filtering_time(worker_i, satb_filtering_ms);
+  g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms);
 
   // Now scan the complement of the collection set.
   if (scan_rs != NULL) {
@@ -5393,7 +5403,7 @@
   assert(pss.refs()->is_empty(), "both queue and overflow should be empty");
 
   double ref_proc_time = os::elapsedTime() - ref_proc_start;
-  g1_policy()->record_ref_proc_time(ref_proc_time * 1000.0);
+  g1_policy()->phase_times()->record_ref_proc_time(ref_proc_time * 1000.0);
 }
 
 // Weak Reference processing during an evacuation pause (part 2).
@@ -5430,7 +5440,7 @@
   // and could signicantly increase the pause time.
 
   double ref_enq_time = os::elapsedTime() - ref_enq_start;
-  g1_policy()->record_ref_enq_time(ref_enq_time * 1000.0);
+  g1_policy()->phase_times()->record_ref_enq_time(ref_enq_time * 1000.0);
 }
 
 void G1CollectedHeap::evacuate_collection_set() {
@@ -5493,11 +5503,11 @@
   }
 
   double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0;
-  g1_policy()->record_par_time(par_time_ms);
+  g1_policy()->phase_times()->record_par_time(par_time_ms);
 
   double code_root_fixup_time_ms =
         (os::elapsedTime() - end_par_time_sec) * 1000.0;
-  g1_policy()->record_code_root_fixup_time(code_root_fixup_time_ms);
+  g1_policy()->phase_times()->record_code_root_fixup_time(code_root_fixup_time_ms);
 
   set_par_threads(0);
 
@@ -5759,7 +5769,7 @@
   }
 
   double elapsed = os::elapsedTime() - start;
-  g1_policy()->record_clear_ct_time(elapsed * 1000.0);
+  g1_policy()->phase_times()->record_clear_ct_time(elapsed * 1000.0);
 }
 
 void G1CollectedHeap::free_collection_set(HeapRegion* cs_head) {
@@ -5868,8 +5878,8 @@
                                     NULL /* old_proxy_set */,
                                     NULL /* humongous_proxy_set */,
                                     false /* par */);
-  policy->record_young_free_cset_time_ms(young_time_ms);
-  policy->record_non_young_free_cset_time_ms(non_young_time_ms);
+  policy->phase_times()->record_young_free_cset_time_ms(young_time_ms);
+  policy->phase_times()->record_non_young_free_cset_time_ms(non_young_time_ms);
 }
 
 // This routine is similar to the above but does not record
--- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp	Tue Jul 17 12:32:26 2012 -0400
+++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp	Tue Jul 17 14:33:17 2012 -0700
@@ -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) {
--- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp	Tue Jul 17 12:32:26 2012 -0400
+++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp	Tue Jul 17 14:33:17 2012 -0700
@@ -36,6 +36,7 @@
 
 class HeapRegion;
 class CollectionSetChooser;
+class G1GCPhaseTimes;
 
 // TraceGen0Time collects data on _both_ young and mixed evacuation pauses
 // (the latter may contain non-young regions - i.e. regions that are
@@ -61,26 +62,14 @@
   NumberSeq _parallel_other;
   NumberSeq _clear_ct;
 
-  void print_summary (int level, const char* str, const NumberSeq* seq) const;
-  void print_summary_sd (int level, const char* str, const NumberSeq* seq) const;
+  void print_summary(const char* str, const NumberSeq* seq) const;
+  void print_summary_sd(const char* str, const NumberSeq* seq) const;
 
 public:
    TraceGen0TimeData() : _young_pause_num(0), _mixed_pause_num(0) {};
   void record_start_collection(double time_to_stop_the_world_ms);
   void record_yield_time(double yield_time_ms);
-  void 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 record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times);
   void increment_young_collection_count();
   void increment_mixed_collection_count();
   void print() const;
@@ -186,25 +175,9 @@
 
   CollectionSetChooser* _collectionSetChooser;
 
-  double _cur_collection_start_sec;
+  double _full_collection_start_sec;
   size_t _cur_collection_pause_used_at_start_bytes;
   uint   _cur_collection_pause_used_regions_at_start;
-  double _cur_collection_par_time_ms;
-
-  double _cur_collection_code_root_fixup_time_ms;
-
-  double _cur_clear_ct_time_ms;
-  double _cur_ref_proc_time_ms;
-  double _cur_ref_enq_time_ms;
-
-#ifndef PRODUCT
-  // Card Table Count Cache stats
-  double _min_clear_cc_time_ms;         // min
-  double _max_clear_cc_time_ms;         // max
-  double _cur_clear_cc_time_ms;         // clearing time during current pause
-  double _cum_clear_cc_time_ms;         // cummulative clearing time
-  jlong  _num_cc_clears;                // number of times the card count cache has been cleared
-#endif
 
   // These exclude marking times.
   TruncatedSeq* _recent_gc_times_ms;
@@ -217,23 +190,6 @@
 
   double _stop_world_start;
 
-  double* _par_last_gc_worker_start_times_ms;
-  double* _par_last_ext_root_scan_times_ms;
-  double* _par_last_satb_filtering_times_ms;
-  double* _par_last_update_rs_times_ms;
-  double* _par_last_update_rs_processed_buffers;
-  double* _par_last_scan_rs_times_ms;
-  double* _par_last_obj_copy_times_ms;
-  double* _par_last_termination_times_ms;
-  double* _par_last_termination_attempts;
-  double* _par_last_gc_worker_end_times_ms;
-  double* _par_last_gc_worker_times_ms;
-
-  // Each workers 'other' time i.e. the elapsed time of the parallel
-  // code executed by a worker minus the sum of the individual sub-phase
-  // times for that worker thread.
-  double* _par_last_gc_worker_other_times_ms;
-
   // indicates whether we are in young or mixed GC mode
   bool _gcs_are_young;
 
@@ -306,10 +262,6 @@
 
   size_t _recorded_rs_lengths;
   size_t _max_rs_lengths;
-
-  double _recorded_young_free_cset_time_ms;
-  double _recorded_non_young_free_cset_time_ms;
-
   double _sigma;
 
   size_t _rs_lengths_prediction;
@@ -341,8 +293,7 @@
   void set_no_of_gc_threads(uintx v) { _no_of_gc_threads = v; }
 
   double _pause_time_target_ms;
-  double _recorded_young_cset_choice_time_ms;
-  double _recorded_non_young_cset_choice_time_ms;
+
   size_t _pending_cards;
   size_t _max_pending_cards;
 
@@ -497,14 +448,6 @@
   uint young_cset_region_length() { return eden_cset_region_length() +
                                            survivor_cset_region_length(); }
 
-  void record_young_free_cset_time_ms(double time_ms) {
-    _recorded_young_free_cset_time_ms = time_ms;
-  }
-
-  void record_non_young_free_cset_time_ms(double time_ms) {
-    _recorded_non_young_free_cset_time_ms = time_ms;
-  }
-
   double predict_survivor_regions_evac_time();
 
   void cset_regions_freed() {
@@ -552,19 +495,6 @@
   }
 
 private:
-  void print_stats(int level, const char* str, double value);
-  void print_stats(int level, const char* str, double value, int workers);
-  void print_stats(int level, const char* str, int value);
-
-  void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
-
-  double avg_value (double* data);
-  double max_value (double* data);
-  double sum_of_values (double* data);
-  double max_sum (double* data1, double* data2);
-
-  double _last_pause_time_ms;
-
   size_t _bytes_in_collection_set_before_gc;
   size_t _bytes_copied_during_gc;
 
@@ -638,6 +568,8 @@
   // Stash a pointer to the g1 heap.
   G1CollectedHeap* _g1;
 
+  G1GCPhaseTimes* _phase_times;
+
   // The ratio of gc time to elapsed time, computed over recent pauses.
   double _recent_avg_pause_time_ratio;
 
@@ -677,7 +609,6 @@
   double _cur_mark_stop_world_time_ms;
   double _mark_remark_start_sec;
   double _mark_cleanup_start_sec;
-  double _root_region_scan_wait_time_ms;
 
   // Update the young list target length either by setting it to the
   // desired fixed value or by calculating it using G1's pause
@@ -728,6 +659,8 @@
     return CollectorPolicy::G1CollectorPolicyKind;
   }
 
+  G1GCPhaseTimes* phase_times() const { return _phase_times; }
+
   // Check the current value of the young list RSet lengths and
   // compare it against the last prediction. If the current value is
   // higher, recalculate the young list target length prediction.
@@ -772,10 +705,6 @@
   void record_concurrent_mark_init_end(double
                                            mark_init_elapsed_time_ms);
 
-  void record_root_region_scan_wait_time(double time_ms) {
-    _root_region_scan_wait_time_ms = time_ms;
-  }
-
   void record_concurrent_mark_remark_start();
   void record_concurrent_mark_remark_end();
 
@@ -784,97 +713,14 @@
   void record_concurrent_mark_cleanup_completed();
 
   void record_concurrent_pause();
-  void record_concurrent_pause_end();
 
-  void record_collection_pause_end(int no_of_gc_threads);
+  void record_collection_pause_end(double pause_time);
   void print_heap_transition();
 
   // Record the fact that a full collection occurred.
   void record_full_collection_start();
   void record_full_collection_end();
 
-  void record_gc_worker_start_time(int worker_i, double ms) {
-    _par_last_gc_worker_start_times_ms[worker_i] = ms;
-  }
-
-  void record_ext_root_scan_time(int worker_i, double ms) {
-    _par_last_ext_root_scan_times_ms[worker_i] = ms;
-  }
-
-  void record_satb_filtering_time(int worker_i, double ms) {
-    _par_last_satb_filtering_times_ms[worker_i] = ms;
-  }
-
-  void record_update_rs_time(int thread, double ms) {
-    _par_last_update_rs_times_ms[thread] = ms;
-  }
-
-  void record_update_rs_processed_buffers (int thread,
-                                           double processed_buffers) {
-    _par_last_update_rs_processed_buffers[thread] = processed_buffers;
-  }
-
-  void record_scan_rs_time(int thread, double ms) {
-    _par_last_scan_rs_times_ms[thread] = ms;
-  }
-
-  void reset_obj_copy_time(int thread) {
-    _par_last_obj_copy_times_ms[thread] = 0.0;
-  }
-
-  void reset_obj_copy_time() {
-    reset_obj_copy_time(0);
-  }
-
-  void record_obj_copy_time(int thread, double ms) {
-    _par_last_obj_copy_times_ms[thread] += ms;
-  }
-
-  void record_termination(int thread, double ms, size_t attempts) {
-    _par_last_termination_times_ms[thread] = ms;
-    _par_last_termination_attempts[thread] = (double) attempts;
-  }
-
-  void record_gc_worker_end_time(int worker_i, double ms) {
-    _par_last_gc_worker_end_times_ms[worker_i] = ms;
-  }
-
-  void record_pause_time_ms(double ms) {
-    _last_pause_time_ms = ms;
-  }
-
-  void record_clear_ct_time(double ms) {
-    _cur_clear_ct_time_ms = ms;
-  }
-
-  void record_par_time(double ms) {
-    _cur_collection_par_time_ms = ms;
-  }
-
-  void record_code_root_fixup_time(double ms) {
-    _cur_collection_code_root_fixup_time_ms = ms;
-  }
-
-  void record_ref_proc_time(double ms) {
-    _cur_ref_proc_time_ms = ms;
-  }
-
-  void record_ref_enq_time(double ms) {
-    _cur_ref_enq_time_ms = ms;
-  }
-
-#ifndef PRODUCT
-  void record_cc_clear_time(double ms) {
-    if (_min_clear_cc_time_ms < 0.0 || ms <= _min_clear_cc_time_ms)
-      _min_clear_cc_time_ms = ms;
-    if (_max_clear_cc_time_ms < 0.0 || ms >= _max_clear_cc_time_ms)
-      _max_clear_cc_time_ms = ms;
-    _cur_clear_cc_time_ms = ms;
-    _cum_clear_cc_time_ms += ms;
-    _num_cc_clears++;
-  }
-#endif
-
   // Record how much space we copied during a GC. This is typically
   // called when a GC alloc region is being retired.
   void record_bytes_copied_during_gc(size_t bytes) {
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp	Tue Jul 17 14:33:17 2012 -0700
@@ -0,0 +1,379 @@
+/*
+ * Copyright (c) 2012, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+
+
+#include "precompiled.hpp"
+#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
+#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
+#include "gc_implementation/g1/g1Log.hpp"
+
+// Helper 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;
+  }
+};
+
+G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
+  _max_gc_threads(max_gc_threads),
+  _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)
+{
+  assert(max_gc_threads > 0, "Must have some GC threads");
+  _par_last_gc_worker_start_times_ms = new double[_max_gc_threads];
+  _par_last_ext_root_scan_times_ms = new double[_max_gc_threads];
+  _par_last_satb_filtering_times_ms = new double[_max_gc_threads];
+  _par_last_update_rs_times_ms = new double[_max_gc_threads];
+  _par_last_update_rs_processed_buffers = new double[_max_gc_threads];
+  _par_last_scan_rs_times_ms = new double[_max_gc_threads];
+  _par_last_obj_copy_times_ms = new double[_max_gc_threads];
+  _par_last_termination_times_ms = new double[_max_gc_threads];
+  _par_last_termination_attempts = new double[_max_gc_threads];
+  _par_last_gc_worker_end_times_ms = new double[_max_gc_threads];
+  _par_last_gc_worker_times_ms = new double[_max_gc_threads];
+  _par_last_gc_worker_other_times_ms = new double[_max_gc_threads];
+}
+
+void G1GCPhaseTimes::note_gc_start(double pause_start_time_sec, uint active_gc_threads,
+  bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause) {
+  assert(active_gc_threads > 0, "The number of threads must be > 0");
+  assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
+  _active_gc_threads = active_gc_threads;
+  _pause_start_time_sec = pause_start_time_sec;
+  _is_young_gc = is_young_gc;
+  _is_initial_mark_gc = is_initial_mark_gc;
+  _gc_cause = gc_cause;
+
+#ifdef ASSERT
+  // initialise the timing data to something well known so that we can spot
+  // if something is not set properly
+
+  for (uint i = 0; i < _max_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
+}
+
+void G1GCPhaseTimes::note_gc_end(double pause_end_time_sec) {
+  if (G1Log::fine()) {
+    double pause_time_ms = (pause_end_time_sec - _pause_start_time_sec) * MILLIUNITS;
+
+    for (uint i = 0; i < _active_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(pause_time_ms);
+  }
+
+}
+
+void G1GCPhaseTimes::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 < _active_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) _active_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 G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
+  LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
+}
+
+void G1GCPhaseTimes::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 G1GCPhaseTimes::print_stats(int level, const char* str, int value) {
+  LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
+}
+
+double G1GCPhaseTimes::avg_value(double* data) {
+  if (G1CollectedHeap::use_parallel_gc_threads()) {
+    double ret = 0.0;
+    for (uint i = 0; i < _active_gc_threads; ++i) {
+      ret += data[i];
+    }
+    return ret / (double) _active_gc_threads;
+  } else {
+    return data[0];
+  }
+}
+
+double G1GCPhaseTimes::max_value(double* data) {
+  if (G1CollectedHeap::use_parallel_gc_threads()) {
+    double ret = data[0];
+    for (uint i = 1; i < _active_gc_threads; ++i) {
+      if (data[i] > ret) {
+        ret = data[i];
+      }
+    }
+    return ret;
+  } else {
+    return data[0];
+  }
+}
+
+double G1GCPhaseTimes::sum_of_values(double* data) {
+  if (G1CollectedHeap::use_parallel_gc_threads()) {
+    double sum = 0.0;
+    for (uint i = 0; i < _active_gc_threads; i++) {
+      sum += data[i];
+    }
+    return sum;
+  } else {
+    return data[0];
+  }
+}
+
+double G1GCPhaseTimes::max_sum(double* data1, double* data2) {
+  double ret = data1[0] + data2[0];
+
+  if (G1CollectedHeap::use_parallel_gc_threads()) {
+    for (uint i = 1; i < _active_gc_threads; ++i) {
+      double data = data1[i] + data2[i];
+      if (data > ret) {
+        ret = data;
+      }
+    }
+  }
+  return ret;
+}
+
+void G1GCPhaseTimes::collapse_par_times() {
+    _ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
+    _satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
+    _update_rs_time = avg_value(_par_last_update_rs_times_ms);
+    _update_rs_processed_buffers =
+      sum_of_values(_par_last_update_rs_processed_buffers);
+    _scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
+    _obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
+    _termination_time = avg_value(_par_last_termination_times_ms);
+}
+
+double G1GCPhaseTimes::accounted_time_ms() {
+    // Subtract the root region scanning wait time. It's initialized to
+    // zero at the start of the pause.
+    double misc_time_ms = _root_region_scan_wait_time_ms;
+
+    misc_time_ms += _cur_collection_par_time_ms;
+
+    // Now subtract the time taken to fix up roots in generated code
+    misc_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"
+    misc_time_ms += _cur_clear_ct_time_ms;
+
+    return misc_time_ms;
+}
+
+void G1GCPhaseTimes::print(double pause_time_ms) {
+
+  if (PrintGCTimeStamps) {
+    gclog_or_tty->stamp();
+    gclog_or_tty->print(": ");
+  }
+
+  GCCauseString gc_cause_str = GCCauseString("GC pause", _gc_cause)
+    .append(_is_young_gc ? " (young)" : " (mixed)")
+    .append(_is_initial_mark_gc ? " (initial-mark)" : "");
+  gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_ms / 1000.0);
+
+  if (!G1Log::finer()) {
+    return;
+  }
+
+  if (_root_region_scan_wait_time_ms > 0.0) {
+    print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
+  }
+  if (G1CollectedHeap::use_parallel_gc_threads()) {
+    print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_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 (_satb_filtering_time > 0.0) {
+      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 */);
+    }
+    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 (_satb_filtering_time > 0.0) {
+      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);
+  if (Verbose && G1Log::finest()) {
+    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));
+    }
+  }
+  double misc_time_ms = pause_time_ms - accounted_time_ms();
+  print_stats(1, "Other", misc_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));
+}
+
+void G1GCPhaseTimes::record_cc_clear_time_ms(double ms) {
+  if (!(Verbose && G1Log::finest())) {
+    return;
+  }
+
+  if (_min_clear_cc_time_ms < 0.0 || ms <= _min_clear_cc_time_ms) {
+    _min_clear_cc_time_ms = ms;
+  }
+  if (_max_clear_cc_time_ms < 0.0 || ms >= _max_clear_cc_time_ms) {
+    _max_clear_cc_time_ms = ms;
+  }
+  _cur_clear_cc_time_ms = ms;
+  _cum_clear_cc_time_ms += ms;
+  _num_cc_clears++;
+}
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp	Tue Jul 17 14:33:17 2012 -0700
@@ -0,0 +1,216 @@
+/*
+ * Copyright (c) 2012, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+
+#ifndef SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
+#define SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
+
+#include "memory/allocation.hpp"
+#include "gc_interface/gcCause.hpp"
+
+class G1GCPhaseTimes : public CHeapObj<mtGC> {
+  friend class G1CollectorPolicy;
+  friend class TraceGen0TimeData;
+
+ private:
+  uint _active_gc_threads;
+  uint _max_gc_threads;
+
+  GCCause::Cause _gc_cause;
+  bool           _is_young_gc;
+  bool           _is_initial_mark_gc;
+
+  double _pause_start_time_sec;
+
+  double* _par_last_gc_worker_start_times_ms;
+  double* _par_last_ext_root_scan_times_ms;
+  double* _par_last_satb_filtering_times_ms;
+  double* _par_last_update_rs_times_ms;
+  double* _par_last_update_rs_processed_buffers;
+  double* _par_last_scan_rs_times_ms;
+  double* _par_last_obj_copy_times_ms;
+  double* _par_last_termination_times_ms;
+  double* _par_last_termination_attempts;
+  double* _par_last_gc_worker_end_times_ms;
+  double* _par_last_gc_worker_times_ms;
+  double* _par_last_gc_worker_other_times_ms;
+
+  double _cur_collection_par_time_ms;
+
+  double _cur_collection_code_root_fixup_time_ms;
+
+  double _cur_clear_ct_time_ms;
+  double _cur_ref_proc_time_ms;
+  double _cur_ref_enq_time_ms;
+
+  // Helper methods for detailed logging
+  void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
+  void print_stats(int level, const char* str, double value);
+  void print_stats(int level, const char* str, double value, int workers);
+  void print_stats(int level, const char* str, int value);
+  double avg_value(double* data);
+  double max_value(double* data);
+  double sum_of_values(double* data);
+  double max_sum(double* data1, double* data2);
+  double accounted_time_ms();
+
+  // Card Table Count Cache stats
+  double _min_clear_cc_time_ms;         // min
+  double _max_clear_cc_time_ms;         // max
+  double _cur_clear_cc_time_ms;         // clearing time during current pause
+  double _cum_clear_cc_time_ms;         // cummulative clearing time
+  jlong  _num_cc_clears;                // number of times the card count cache has been cleared
+
+  // The following insance variables are directly accessed by G1CollectorPolicy
+  // and TraceGen0TimeData. This is why those classes are declared friends.
+  // An alternative is to add getters and setters for all of these fields.
+  // It might also be possible to restructure the code to reduce these
+  // dependencies.
+  double _ext_root_scan_time;
+  double _satb_filtering_time;
+  double _update_rs_time;
+  double _update_rs_processed_buffers;
+  double _scan_rs_time;
+  double _obj_copy_time;
+  double _termination_time;
+
+  double _cur_collection_start_sec;
+  double _root_region_scan_wait_time_ms;
+
+  double _recorded_young_cset_choice_time_ms;
+  double _recorded_non_young_cset_choice_time_ms;
+
+  double _recorded_young_free_cset_time_ms;
+  double _recorded_non_young_free_cset_time_ms;
+
+  void print(double pause_time_ms);
+
+ public:
+  G1GCPhaseTimes(uint max_gc_threads);
+  void note_gc_start(double pause_start_time_sec, uint active_gc_threads,
+    bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause);
+  void note_gc_end(double pause_end_time_sec);
+  void collapse_par_times();
+
+  void record_gc_worker_start_time(uint worker_i, double ms) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_gc_worker_start_times_ms[worker_i] = ms;
+  }
+
+  void record_ext_root_scan_time(uint worker_i, double ms) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_ext_root_scan_times_ms[worker_i] = ms;
+  }
+
+  void record_satb_filtering_time(uint worker_i, double ms) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_satb_filtering_times_ms[worker_i] = ms;
+  }
+
+  void record_update_rs_time(uint worker_i, double ms) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_update_rs_times_ms[worker_i] = ms;
+  }
+
+  void record_update_rs_processed_buffers (uint worker_i,
+                                           double processed_buffers) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_update_rs_processed_buffers[worker_i] = processed_buffers;
+  }
+
+  void record_scan_rs_time(uint worker_i, double ms) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_scan_rs_times_ms[worker_i] = ms;
+  }
+
+  void reset_obj_copy_time(uint worker_i) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_obj_copy_times_ms[worker_i] = 0.0;
+  }
+
+  void reset_obj_copy_time() {
+    reset_obj_copy_time(0);
+  }
+
+  void record_obj_copy_time(uint worker_i, double ms) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_obj_copy_times_ms[worker_i] += ms;
+  }
+
+  void record_termination(uint worker_i, double ms, size_t attempts) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_termination_times_ms[worker_i] = ms;
+    _par_last_termination_attempts[worker_i] = (double) attempts;
+  }
+
+  void record_gc_worker_end_time(uint worker_i, double ms) {
+    assert(worker_i >= 0, "worker index must be > 0");
+    assert(worker_i < _active_gc_threads, "worker index out of bounds");
+    _par_last_gc_worker_end_times_ms[worker_i] = ms;
+  }
+
+  void record_clear_ct_time(double ms) {
+    _cur_clear_ct_time_ms = ms;
+  }
+
+  void record_par_time(double ms) {
+    _cur_collection_par_time_ms = ms;
+  }
+
+  void record_code_root_fixup_time(double ms) {
+    _cur_collection_code_root_fixup_time_ms = ms;
+  }
+
+  void record_ref_proc_time(double ms) {
+    _cur_ref_proc_time_ms = ms;
+  }
+
+  void record_ref_enq_time(double ms) {
+    _cur_ref_enq_time_ms = ms;
+  }
+
+  void record_root_region_scan_wait_time(double time_ms) {
+    _root_region_scan_wait_time_ms = time_ms;
+  }
+
+  void record_cc_clear_time_ms(double ms);
+
+  void record_young_free_cset_time_ms(double time_ms) {
+    _recorded_young_free_cset_time_ms = time_ms;
+  }
+
+  void record_non_young_free_cset_time_ms(double time_ms) {
+    _recorded_non_young_free_cset_time_ms = time_ms;
+  }
+};
+
+#endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
--- a/src/share/vm/gc_implementation/g1/g1RemSet.cpp	Tue Jul 17 12:32:26 2012 -0400
+++ b/src/share/vm/gc_implementation/g1/g1RemSet.cpp	Tue Jul 17 14:33:17 2012 -0700
@@ -29,6 +29,7 @@
 #include "gc_implementation/g1/g1BlockOffsetTable.inline.hpp"
 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
 #include "gc_implementation/g1/g1CollectorPolicy.hpp"
+#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
 #include "gc_implementation/g1/g1OopClosures.inline.hpp"
 #include "gc_implementation/g1/g1RemSet.inline.hpp"
 #include "gc_implementation/g1/heapRegionSeq.inline.hpp"
@@ -224,7 +225,7 @@
   assert( _cards_scanned != NULL, "invariant" );
   _cards_scanned[worker_i] = scanRScl.cards_done();
 
-  _g1p->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0);
+  _g1p->phase_times()->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0);
 }
 
 // Closure used for updating RSets and recording references that
@@ -276,7 +277,7 @@
     guarantee(cl.n() == 0, "Card table should be clean.");
   }
 
-  _g1p->record_update_rs_time(worker_i, (os::elapsedTime() - start) * 1000.0);
+  _g1p->phase_times()->record_update_rs_time(worker_i, (os::elapsedTime() - start) * 1000.0);
 }
 
 class CountRSSizeClosure: public HeapRegionClosure {
@@ -390,13 +391,13 @@
   if (G1UseParallelRSetUpdating || (worker_i == 0)) {
     updateRS(&into_cset_dcq, worker_i);
   } else {
-    _g1p->record_update_rs_processed_buffers(worker_i, 0.0);
-    _g1p->record_update_rs_time(worker_i, 0.0);
+    _g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0.0);
+    _g1p->phase_times()->record_update_rs_time(worker_i, 0.0);
   }
   if (G1UseParallelRSetScanning || (worker_i == 0)) {
     scanRS(oc, worker_i);
   } else {
-    _g1p->record_scan_rs_time(worker_i, 0.0);
+    _g1p->phase_times()->record_scan_rs_time(worker_i, 0.0);
   }
 
   // We now clear the cached values of _cset_rs_update_cl for this worker