--- old/src/share/vm/gc/g1/g1CollectedHeap.cpp 2016-02-01 10:51:53.286963990 +0100 +++ new/src/share/vm/gc/g1/g1CollectedHeap.cpp 2016-02-01 10:51:53.162963985 +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 --- old/src/share/vm/gc/g1/g1CollectedHeap.hpp 2016-02-01 10:51:53.558964002 +0100 +++ new/src/share/vm/gc/g1/g1CollectedHeap.hpp 2016-02-01 10:51:53.434963997 +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); --- old/src/share/vm/gc/g1/g1CollectorPolicy.cpp 2016-02-01 10:51:53.782964011 +0100 +++ new/src/share/vm/gc/g1/g1CollectorPolicy.cpp 2016-02-01 10:51:53.662964006 +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, --- old/src/share/vm/gc/g1/g1CollectorPolicy.hpp 2016-02-01 10:51:54.034964022 +0100 +++ new/src/share/vm/gc/g1/g1CollectorPolicy.hpp 2016-02-01 10:51:53.906964016 +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(); --- old/src/share/vm/gc/g1/g1GCPhaseTimes.cpp 2016-02-01 10:51:54.250964031 +0100 +++ new/src/share/vm/gc/g1/g1GCPhaseTimes.cpp 2016-02-01 10:51:54.122964025 +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); --- old/src/share/vm/gc/g1/g1GCPhaseTimes.hpp 2016-02-01 10:51:54.482964040 +0100 +++ new/src/share/vm/gc/g1/g1GCPhaseTimes.hpp 2016-02-01 10:51:54.350964035 +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);