8201596: java.lang.ref.Reference processing total time logging broken
authortschatzl
Wed, 18 Apr 2018 11:36:48 +0200
changeset 49810 b5d5e53232ce
parent 49809 ef5220d644e3
child 49811 bfba4712d4ff
8201596: java.lang.ref.Reference processing total time logging broken Summary: Fix "Reference Processing" and add "Weak Processing" time Reviewed-by: kbarrett, sangheki
src/hotspot/share/gc/g1/g1CollectedHeap.cpp
src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp
test/hotspot/jtreg/gc/g1/TestGCLogMessages.java
--- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp	Wed Apr 18 11:36:48 2018 +0200
+++ b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp	Wed Apr 18 11:36:48 2018 +0200
@@ -4201,7 +4201,7 @@
     WeakProcessor::weak_oops_do(&is_alive, &keep_alive);
 
     double time_ms = (os::elapsedTime() - start) * 1000.0;
-    g1_policy()->phase_times()->record_ref_proc_time(time_ms);
+    g1_policy()->phase_times()->record_weak_ref_proc_time(time_ms);
   }
 
   if (G1StringDedup::is_enabled()) {
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp	Wed Apr 18 11:36:48 2018 +0200
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp	Wed Apr 18 11:36:48 2018 +0200
@@ -131,6 +131,7 @@
   _cur_expand_heap_time_ms = 0.0;
   _cur_ref_proc_time_ms = 0.0;
   _cur_ref_enq_time_ms = 0.0;
+  _cur_weak_ref_proc_time_ms = 0.0;
   _cur_collection_start_sec = 0.0;
   _root_region_scan_wait_time_ms = 0.0;
   _external_accounted_time_ms = 0.0;
@@ -372,6 +373,7 @@
                         _cur_collection_code_root_fixup_time_ms +
                         _recorded_preserve_cm_referents_time_ms +
                         _cur_ref_proc_time_ms +
+                        _cur_weak_ref_proc_time_ms +
                         _cur_ref_enq_time_ms +
                         _cur_clear_ct_time_ms +
                         _recorded_merge_pss_time_ms +
@@ -392,6 +394,8 @@
   debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
   _ref_phase_times.print_all_references(2, false);
 
+  debug_time("Weak Processing", _cur_weak_ref_proc_time_ms);
+
   if (G1StringDedup::is_enabled()) {
     debug_time("String Dedup Fixup", _cur_string_dedup_fixup_time_ms);
     debug_phase(_gc_par_phases[StringDedupQueueFixup]);
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp	Wed Apr 18 11:36:48 2018 +0200
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp	Wed Apr 18 11:36:48 2018 +0200
@@ -129,6 +129,8 @@
   double _cur_ref_proc_time_ms;
   double _cur_ref_enq_time_ms;
 
+  double _cur_weak_ref_proc_time_ms;
+
   double _cur_collection_start_sec;
   double _root_region_scan_wait_time_ms;
 
@@ -253,6 +255,10 @@
     _cur_ref_proc_time_ms = ms;
   }
 
+  void record_weak_ref_proc_time(double ms) {
+    _cur_weak_ref_proc_time_ms = ms;
+  }
+
   void record_ref_enq_time(double ms) {
     _cur_ref_enq_time_ms = ms;
   }
--- a/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java	Wed Apr 18 11:36:48 2018 +0200
+++ b/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java	Wed Apr 18 11:36:48 2018 +0200
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2014, 2017, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2014, 2018, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -144,6 +144,8 @@
         // Reference Processing
         new LogMessageWithLevel("Reference Processing", Level.DEBUG),
         new LogMessageWithLevel("Reference Enqueuing", Level.DEBUG),
+        // VM internal reference processing
+        new LogMessageWithLevel("Weak Processing", Level.DEBUG),
 
         new LogMessageWithLevelC2OrJVMCIOnly("DerivedPointerTable Update", Level.DEBUG),
         new LogMessageWithLevel("Start New Collection Set", Level.DEBUG),