8150630: Add logging for ParScanThreadState merge phase
authortschatzl
Fri, 26 Feb 2016 13:02:30 +0100
changeset 36368 569d6e8072a9
parent 36367 313c87c050f7
child 36369 f4c151403480
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
hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp
hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp
hotspot/test/gc/g1/TestGCLogMessages.java
--- 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 {