8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
authorbrutisso
Tue, 02 Feb 2016 10:50:08 +0100
changeset 35907 57bdb6243428
parent 35905 7a7ad93cf358
child 35908 cb12f847b199
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time Reviewed-by: sjohanss, tschatzl
hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp
hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp
hotspot/src/share/vm/gc/g1/g1CollectorPolicy.cpp
hotspot/src/share/vm/gc/g1/g1CollectorPolicy.hpp
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Tue Feb 02 09:51:24 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Tue Feb 02 10:50:08 2016 +0100
@@ -3169,13 +3169,12 @@
 }
 #endif // TASKQUEUE_STATS
 
-void G1CollectedHeap::log_gc_footer(jlong pause_time_counter) {
+void G1CollectedHeap::log_gc_footer() {
   if (evacuation_failed()) {
     log_info(gc)("To-space exhausted");
   }
 
-  double pause_time_ms = TimeHelper::counter_to_millis(pause_time_counter);
-  g1_policy()->print_phases(pause_time_ms);
+  g1_policy()->print_phases();
 
   g1_policy()->print_detailed_heap_transition();
 }
@@ -3267,7 +3266,6 @@
     }
     GCTraceTime(Info, gc) tm(gc_string, NULL, gc_cause(), true);
 
-    jlong pause_start_counter = os::elapsed_counter();
     g1_policy()->note_gc_start(active_workers);
 
     TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
@@ -3529,7 +3527,7 @@
     }
 
     // Print the remainder of the GC log output.
-    log_gc_footer(os::elapsed_counter() - pause_start_counter);
+    log_gc_footer();
 
     // 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
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp	Tue Feb 02 09:51:24 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp	Tue Feb 02 10:50:08 2016 +0100
@@ -291,7 +291,7 @@
                                                          size_t size,
                                                          size_t translation_factor);
 
-  void log_gc_footer(jlong pause_time_counter);
+  void log_gc_footer();
 
   void trace_heap(GCWhen::Type when, const GCTracer* tracer);
 
--- a/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.cpp	Tue Feb 02 09:51:24 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.cpp	Tue Feb 02 10:50:08 2016 +0100
@@ -1303,8 +1303,8 @@
   MetaspaceAux::print_metaspace_change(_metaspace_used_bytes_before_gc);
 }
 
-void G1CollectorPolicy::print_phases(double pause_time_ms) {
-  phase_times()->print(pause_time_ms);
+void G1CollectorPolicy::print_phases() {
+  phase_times()->print();
 }
 
 void G1CollectorPolicy::adjust_concurrent_refinement(double update_rs_time,
--- a/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.hpp	Tue Feb 02 09:51:24 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.hpp	Tue Feb 02 10:50:08 2016 +0100
@@ -662,7 +662,7 @@
 
   void print_detailed_heap_transition() const;
 
-  virtual void print_phases(double pause_time_ms);
+  virtual void print_phases();
 
   void record_stop_world_start();
   void record_concurrent_pause();
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Tue Feb 02 09:51:24 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Tue Feb 02 10:50:08 2016 +0100
@@ -30,6 +30,7 @@
 #include "gc/g1/workerDataArray.inline.hpp"
 #include "memory/allocation.hpp"
 #include "logging/log.hpp"
+#include "runtime/timer.hpp"
 #include "runtime/os.hpp"
 
 // Helper class for avoiding interleaved logging
@@ -133,6 +134,7 @@
 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
   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 number of threads");
+  _gc_start_counter = os::elapsed_counter();
   _active_gc_threads = active_gc_threads;
   _cur_expand_heap_time_ms = 0.0;
   _external_accounted_time_ms = 0.0;
@@ -146,6 +148,7 @@
 }
 
 void G1GCPhaseTimes::note_gc_end() {
+  _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
   for (uint i = 0; i < _active_gc_threads; i++) {
     double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
     record_time_secs(GCWorkerTotal, i , worker_time);
@@ -349,7 +352,7 @@
   }
 };
 
-void G1GCPhaseTimes::print(double pause_time_ms) {
+void G1GCPhaseTimes::print() {
   note_gc_end();
 
   G1GCParPhasePrinter par_phase_printer(this);
@@ -373,7 +376,7 @@
   }
   print_stats(Indents[1], "Clear CT", _cur_clear_ct_time_ms);
   print_stats(Indents[1], "Expand Heap After Collection", _cur_expand_heap_time_ms);
-  double misc_time_ms = pause_time_ms - accounted_time_ms();
+  double misc_time_ms = _gc_pause_time_ms - accounted_time_ms();
   print_stats(Indents[1], "Other", misc_time_ms);
   if (_cur_verify_before_time_ms > 0.0) {
     print_stats(Indents[2], "Verify Before", _cur_verify_before_time_ms);
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Tue Feb 02 09:51:24 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Tue Feb 02 10:50:08 2016 +0100
@@ -36,6 +36,8 @@
 
   uint _active_gc_threads;
   uint _max_gc_threads;
+  jlong _gc_start_counter;
+  double _gc_pause_time_ms;
 
  public:
   enum GCParPhases {
@@ -126,7 +128,7 @@
  public:
   G1GCPhaseTimes(uint max_gc_threads);
   void note_gc_start(uint active_gc_threads);
-  void print(double pause_time_ms);
+  void print();
 
   // record the time a phase took in seconds
   void record_time_secs(GCParPhases phase, uint worker_i, double secs);