8150630: Add logging for ParScanThreadState merge phase
Summary: Improve visibility of the per-thread scan state merge phase by adding appropriate logging.
Reviewed-by: jmasa, tbenson
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp Fri Feb 26 13:02:30 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp Fri Feb 26 13:02:30 2016 +0100
@@ -4594,6 +4594,12 @@
g1_policy()->phase_times()->record_ref_enq_time(ref_enq_time * 1000.0);
}
+void G1CollectedHeap::merge_per_thread_state_info(G1ParScanThreadStateSet* per_thread_states) {
+ double merge_pss_time_start = os::elapsedTime();
+ per_thread_states->flush();
+ g1_policy()->phase_times()->record_merge_pss_time_ms((os::elapsedTime() - merge_pss_time_start) * 1000.0);
+}
+
void G1CollectedHeap::pre_evacuate_collection_set() {
_expand_heap_after_alloc_failure = true;
_evacuation_failed = false;
@@ -4696,7 +4702,7 @@
_allocator->release_gc_alloc_regions(evacuation_info);
- per_thread_states->flush();
+ merge_per_thread_state_info(per_thread_states);
record_obj_copy_mem_stats();
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp Fri Feb 26 13:02:30 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp Fri Feb 26 13:02:30 2016 +0100
@@ -522,6 +522,9 @@
// after processing.
void enqueue_discovered_references(G1ParScanThreadStateSet* per_thread_states);
+ // Merges the information gathered on a per-thread basis for all worker threads
+ // during GC into global variables.
+ void merge_per_thread_state_info(G1ParScanThreadStateSet* per_thread_states);
public:
WorkGang* workers() const { return _workers; }
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp Fri Feb 26 13:02:30 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp Fri Feb 26 13:02:30 2016 +0100
@@ -413,6 +413,7 @@
_recorded_non_young_free_cset_time_ms));
log_trace(gc, phases)("%sYoung Free CSet: %.1lf ms", Indents[3], _recorded_young_free_cset_time_ms);
log_trace(gc, phases)("%sNon-Young Free CSet: %.1lf ms", Indents[3], _recorded_non_young_free_cset_time_ms);
+ print_stats(Indents[2], "Merge Per-Thread State", _recorded_merge_pss_time_ms);
if (_cur_verify_after_time_ms > 0.0) {
print_stats(Indents[2], "Verify After", _cur_verify_after_time_ms);
}
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp Fri Feb 26 13:02:30 2016 +0100
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp Fri Feb 26 13:02:30 2016 +0100
@@ -111,6 +111,8 @@
double _recorded_preserve_cm_referents_time_ms;
+ double _recorded_merge_pss_time_ms;
+
double _recorded_young_free_cset_time_ms;
double _recorded_non_young_free_cset_time_ms;
@@ -241,6 +243,10 @@
_recorded_preserve_cm_referents_time_ms = time_ms;
}
+ void record_merge_pss_time_ms(double time_ms) {
+ _recorded_merge_pss_time_ms = time_ms;
+ }
+
void record_cur_collection_start_sec(double time_ms) {
_cur_collection_start_sec = time_ms;
}
--- a/hotspot/test/gc/g1/TestGCLogMessages.java Fri Feb 26 13:02:30 2016 +0100
+++ b/hotspot/test/gc/g1/TestGCLogMessages.java Fri Feb 26 13:02:30 2016 +0100
@@ -23,7 +23,7 @@
/*
* @test TestGCLogMessages
- * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962 8069330 8076463
+ * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962 8069330 8076463 8150630
* @summary Ensure the output for a minor GC with G1
* includes the expected necessary messages.
* @key gc
@@ -88,6 +88,8 @@
new LogMessageWithLevel("Humongous Register", Level.DEBUG),
// Preserve CM Referents
new LogMessageWithLevel("Preserve CM Refs", Level.DEBUG),
+ // Merge PSS
+ new LogMessageWithLevel("Merge Per-Thread State", Level.DEBUG),
};
void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception {