8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
Reviewed-by: sjohanss, tschatzl
--- 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);