7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause

Summary: Also reviewed by: vitalyd@gmail.com. Move the timing out of G1CollectorPolicy into the G1GCPhaseTimes class
Reviewed-by: johnc

src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp

 /*
- * 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 @@ bool ConcurrentG1Refine::expand_card_count_cache(int cache_size_idx) {
 }
 
 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 @@ void ConcurrentG1Refine::clear_and_record_card_counts() {
   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 {

src/share/vm/gc_implementation/g1/concurrentMark.cpp

@@ -3153,9 +3153,6 @@ bool ConcurrentMark::do_yield_check(uint worker_id) {
       _g1h->g1_policy()->record_concurrent_pause();
     }
     cmThread()->yield();
-    if (worker_id == 0) {
-      _g1h->g1_policy()->record_concurrent_pause_end();
-    }
     return true;
   } else {
     return false;

src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp

@@ -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 @@ void G1CollectedHeap::iterate_dirty_card_closure(CardTableEntryClosure* cl,
   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 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
     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 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
         // 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 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
         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 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
         // 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 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
                                  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 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
       // 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 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
 #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 @@ public:
     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 @@ public:
         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 @@ public:
     }
 
     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 @@ g1_process_strong_roots(bool collecting_perm_gen,
 
   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 @@ g1_process_strong_roots(bool collecting_perm_gen,
     }
   }
   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 @@ void G1CollectedHeap::process_discovered_references() {
   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 @@ void G1CollectedHeap::enqueue_discovered_references() {
   // 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 @@ void G1CollectedHeap::evacuate_collection_set() {
   }
 
   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 @@ void G1CollectedHeap::cleanUpCardTable() {
   }
 
   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 @@ void G1CollectedHeap::free_collection_set(HeapRegion* cs_head) {
                                     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

src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp

@@ -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 @@ class TraceGen0TimeData : public CHeapObj {
   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 @@ private:
 
   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 @@ private:
 
   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 @@ private:
 
   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 @@ private:
   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 @@ public:
   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 @@ public:
   }
 
 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 @@ private:
   // 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 @@ private:
   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 @@ public:
     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 @@ public:
   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 @@ public:
   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) {

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

+/*
+ * 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++;
+}

src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp

+/*
+ * 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 {
+  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

src/share/vm/gc_implementation/g1/g1RemSet.cpp

@@ -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 @@ void G1RemSet::scanRS(OopsInHeapRegionClosure* oc, int worker_i) {
   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 @@ void G1RemSet::updateRS(DirtyCardQueue* into_cset_dcq, int worker_i) {
     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 @@ void G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc,
   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