changeset 9392:a4ae74ca2403

8136991: [REDO] Additional number of processed references printed with -XX:+PrintReferenceGC after JDK-8047125 Reviewed-by: kbarrett, tschatzl
author brutisso
date Mon, 28 Sep 2015 09:28:53 +0200
parents d4dec7270392
children 142f04931a09
files src/share/vm/gc/g1/concurrentMark.cpp src/share/vm/gc/shared/gcTraceTime.cpp src/share/vm/gc/shared/gcTraceTime.hpp src/share/vm/gc/shared/referenceProcessor.cpp src/share/vm/gc/shared/referenceProcessor.hpp test/gc/logging/TestPrintReferences.java
diffstat 6 files changed, 127 insertions(+), 54 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/gc/g1/concurrentMark.cpp	Thu Sep 24 18:48:50 2015 +0300
+++ b/src/share/vm/gc/g1/concurrentMark.cpp	Mon Sep 28 09:28:53 2015 +0200
@@ -1235,7 +1235,8 @@
 }
 
 // Helper class to get rid of some boilerplate code.
-class G1CMTraceTime : public GCTraceTime {
+class G1CMTraceTime : public StackObj {
+  GCTraceTimeImpl _gc_trace_time;
   static bool doit_and_prepend(bool doit) {
     if (doit) {
       gclog_or_tty->put(' ');
@@ -1245,7 +1246,7 @@
 
  public:
   G1CMTraceTime(const char* title, bool doit)
-    : GCTraceTime(title, doit_and_prepend(doit), false, G1CollectedHeap::heap()->gc_timer_cm(),
+    : _gc_trace_time(title, doit_and_prepend(doit), false, G1CollectedHeap::heap()->gc_timer_cm(),
         G1CollectedHeap::heap()->concurrent_mark()->concurrent_gc_id()) {
   }
 };
--- a/src/share/vm/gc/shared/gcTraceTime.cpp	Thu Sep 24 18:48:50 2015 +0300
+++ b/src/share/vm/gc/shared/gcTraceTime.cpp	Mon Sep 28 09:28:53 2015 +0200
@@ -35,7 +35,7 @@
 #include "utilities/ticks.inline.hpp"
 
 
-GCTraceTime::GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer, GCId gc_id) :
+GCTraceTimeImpl::GCTraceTimeImpl(const char* title, bool doit, bool print_cr, GCTimer* timer, GCId gc_id) :
     _title(title), _doit(doit), _print_cr(print_cr), _timer(timer), _start_counter() {
   if (_doit || _timer != NULL) {
     _start_counter.stamp();
@@ -59,7 +59,7 @@
   }
 }
 
-GCTraceTime::~GCTraceTime() {
+GCTraceTimeImpl::~GCTraceTimeImpl() {
   Ticks stop_counter;
 
   if (_doit || _timer != NULL) {
--- a/src/share/vm/gc/shared/gcTraceTime.hpp	Thu Sep 24 18:48:50 2015 +0300
+++ b/src/share/vm/gc/shared/gcTraceTime.hpp	Mon Sep 28 09:28:53 2015 +0200
@@ -26,12 +26,13 @@
 #define SHARE_VM_GC_SHARED_GCTRACETIME_HPP
 
 #include "gc/shared/gcTrace.hpp"
+#include "memory/allocation.hpp"
 #include "prims/jni_md.h"
 #include "utilities/ticks.hpp"
 
 class GCTimer;
 
-class GCTraceTime {
+class GCTraceTimeImpl VALUE_OBJ_CLASS_SPEC {
   const char* _title;
   bool _doit;
   bool _print_cr;
@@ -39,8 +40,16 @@
   Ticks _start_counter;
 
  public:
-  GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer, GCId gc_id);
-  ~GCTraceTime();
+  GCTraceTimeImpl(const char* title, bool doit, bool print_cr, GCTimer* timer, GCId gc_id);
+  ~GCTraceTimeImpl();
+};
+
+class GCTraceTime : public StackObj {
+  GCTraceTimeImpl _gc_trace_time_impl;
+
+ public:
+  GCTraceTime(const char* title, bool doit, bool print_cr, GCTimer* timer, GCId gc_id) :
+    _gc_trace_time_impl(title, doit, print_cr, timer, gc_id) {};
 };
 
 #endif // SHARE_VM_GC_SHARED_GCTRACETIME_HPP
--- a/src/share/vm/gc/shared/referenceProcessor.cpp	Thu Sep 24 18:48:50 2015 +0300
+++ b/src/share/vm/gc/shared/referenceProcessor.cpp	Mon Sep 28 09:28:53 2015 +0200
@@ -31,6 +31,7 @@
 #include "gc/shared/gcTraceTime.hpp"
 #include "gc/shared/referencePolicy.hpp"
 #include "gc/shared/referenceProcessor.hpp"
+#include "memory/allocation.hpp"
 #include "oops/oop.inline.hpp"
 #include "runtime/java.hpp"
 #include "runtime/jniHandles.hpp"
@@ -182,6 +183,21 @@
   return total;
 }
 
+static void log_ref_count(size_t count, bool doit) {
+  if (doit) {
+    gclog_or_tty->print(", " SIZE_FORMAT " refs", count);
+  }
+}
+
+class GCRefTraceTime : public StackObj {
+  GCTraceTimeImpl _gc_trace_time;
+ public:
+  GCRefTraceTime(const char* title, bool doit, GCTimer* timer, GCId gc_id, size_t count) :
+    _gc_trace_time(title, doit, false, timer, gc_id) {
+    log_ref_count(count, doit);
+  }
+};
+
 ReferenceProcessorStats ReferenceProcessor::process_discovered_references(
   BoolObjectClosure*           is_alive,
   OopClosure*                  keep_alive,
@@ -206,48 +222,48 @@
 
   bool trace_time = PrintGCDetails && PrintReferenceGC;
 
+  // Include cleaners in phantom statistics.  We expect Cleaner
+  // references to be temporary, and don't want to deal with
+  // possible incompatibilities arising from making it more visible.
+  ReferenceProcessorStats stats(
+      total_count(_discoveredSoftRefs),
+      total_count(_discoveredWeakRefs),
+      total_count(_discoveredFinalRefs),
+      total_count(_discoveredPhantomRefs) + total_count(_discoveredCleanerRefs));
+
   // Soft references
-  size_t soft_count = 0;
   {
-    GCTraceTime tt("SoftReference", trace_time, false, gc_timer, gc_id);
-    soft_count =
-      process_discovered_reflist(_discoveredSoftRefs, _current_soft_ref_policy, true,
-                                 is_alive, keep_alive, complete_gc, task_executor);
+    GCRefTraceTime tt("SoftReference", trace_time, gc_timer, gc_id, stats.soft_count());
+    process_discovered_reflist(_discoveredSoftRefs, _current_soft_ref_policy, true,
+                               is_alive, keep_alive, complete_gc, task_executor);
   }
 
   update_soft_ref_master_clock();
 
   // Weak references
-  size_t weak_count = 0;
   {
-    GCTraceTime tt("WeakReference", trace_time, false, gc_timer, gc_id);
-    weak_count =
-      process_discovered_reflist(_discoveredWeakRefs, NULL, true,
-                                 is_alive, keep_alive, complete_gc, task_executor);
+    GCRefTraceTime tt("WeakReference", trace_time, gc_timer, gc_id, stats.weak_count());
+    process_discovered_reflist(_discoveredWeakRefs, NULL, true,
+                               is_alive, keep_alive, complete_gc, task_executor);
   }
 
   // Final references
-  size_t final_count = 0;
   {
-    GCTraceTime tt("FinalReference", trace_time, false, gc_timer, gc_id);
-    final_count =
-      process_discovered_reflist(_discoveredFinalRefs, NULL, false,
-                                 is_alive, keep_alive, complete_gc, task_executor);
+    GCRefTraceTime tt("FinalReference", trace_time, gc_timer, gc_id, stats.final_count());
+    process_discovered_reflist(_discoveredFinalRefs, NULL, false,
+                               is_alive, keep_alive, complete_gc, task_executor);
   }
 
   // Phantom references
-  size_t phantom_count = 0;
   {
-    GCTraceTime tt("PhantomReference", trace_time, false, gc_timer, gc_id);
-    phantom_count =
-      process_discovered_reflist(_discoveredPhantomRefs, NULL, false,
-                                 is_alive, keep_alive, complete_gc, task_executor);
+    GCRefTraceTime tt("PhantomReference", trace_time, gc_timer, gc_id, stats.phantom_count());
+    process_discovered_reflist(_discoveredPhantomRefs, NULL, false,
+                               is_alive, keep_alive, complete_gc, task_executor);
 
-    // Process cleaners, but include them in phantom statistics.  We expect
+    // Process cleaners, but include them in phantom timing.  We expect
     // Cleaner references to be temporary, and don't want to deal with
     // possible incompatibilities arising from making it more visible.
-    phantom_count +=
-      process_discovered_reflist(_discoveredCleanerRefs, NULL, true,
+    process_discovered_reflist(_discoveredCleanerRefs, NULL, true,
                                  is_alive, keep_alive, complete_gc, task_executor);
   }
 
@@ -258,13 +274,14 @@
   // resurrect a "post-mortem" object.
   {
     GCTraceTime tt("JNI Weak Reference", trace_time, false, gc_timer, gc_id);
+    NOT_PRODUCT(log_ref_count(count_jni_refs(), trace_time);)
     if (task_executor != NULL) {
       task_executor->set_single_threaded_mode();
     }
     process_phaseJNI(is_alive, keep_alive, complete_gc);
   }
 
-  return ReferenceProcessorStats(soft_count, weak_count, final_count, phantom_count);
+  return stats;
 }
 
 #ifndef PRODUCT
@@ -294,12 +311,6 @@
 void ReferenceProcessor::process_phaseJNI(BoolObjectClosure* is_alive,
                                           OopClosure*        keep_alive,
                                           VoidClosure*       complete_gc) {
-#ifndef PRODUCT
-  if (PrintGCDetails && PrintReferenceGC) {
-    unsigned int count = count_jni_refs();
-    gclog_or_tty->print(", %u refs", count);
-  }
-#endif
   JNIHandles::weak_oops_do(is_alive, keep_alive);
   complete_gc->do_void();
 }
@@ -826,8 +837,7 @@
   balance_queues(_discoveredCleanerRefs);
 }
 
-size_t
-ReferenceProcessor::process_discovered_reflist(
+void ReferenceProcessor::process_discovered_reflist(
   DiscoveredList               refs_lists[],
   ReferencePolicy*             policy,
   bool                         clear_referent,
@@ -850,12 +860,6 @@
     balance_queues(refs_lists);
   }
 
-  size_t total_list_count = total_count(refs_lists);
-
-  if (PrintReferenceGC && PrintGCDetails) {
-    gclog_or_tty->print(", " SIZE_FORMAT " refs", total_list_count);
-  }
-
   // Phase 1 (soft refs only):
   // . Traverse the list and remove any SoftReferences whose
   //   referents are not alive, but that should be kept alive for
@@ -898,8 +902,6 @@
                      is_alive, keep_alive, complete_gc);
     }
   }
-
-  return total_list_count;
 }
 
 inline DiscoveredList* ReferenceProcessor::get_discovered_list(ReferenceType rt) {
--- a/src/share/vm/gc/shared/referenceProcessor.hpp	Thu Sep 24 18:48:50 2015 +0300
+++ b/src/share/vm/gc/shared/referenceProcessor.hpp	Mon Sep 28 09:28:53 2015 +0200
@@ -263,13 +263,13 @@
   }
 
   // Process references with a certain reachability level.
-  size_t process_discovered_reflist(DiscoveredList               refs_lists[],
-                                    ReferencePolicy*             policy,
-                                    bool                         clear_referent,
-                                    BoolObjectClosure*           is_alive,
-                                    OopClosure*                  keep_alive,
-                                    VoidClosure*                 complete_gc,
-                                    AbstractRefProcTaskExecutor* task_executor);
+  void process_discovered_reflist(DiscoveredList               refs_lists[],
+                                  ReferencePolicy*             policy,
+                                  bool                         clear_referent,
+                                  BoolObjectClosure*           is_alive,
+                                  OopClosure*                  keep_alive,
+                                  VoidClosure*                 complete_gc,
+                                  AbstractRefProcTaskExecutor* task_executor);
 
   void process_phaseJNI(BoolObjectClosure* is_alive,
                         OopClosure*        keep_alive,
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/test/gc/logging/TestPrintReferences.java	Mon Sep 28 09:28:53 2015 +0200
@@ -0,0 +1,61 @@
+/*
+ * Copyright (c) 2015, 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
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test TestPrintReferences
+ * @bug 8136991
+ * @summary Validate the reference processing logging
+ * @key gc
+ * @library /testlibrary
+ * @modules java.base/sun.misc
+ *          java.management
+ */
+
+import jdk.test.lib.ProcessTools;
+import jdk.test.lib.OutputAnalyzer;
+
+public class TestPrintReferences {
+  public static void main(String[] args) throws Exception {
+    ProcessBuilder pb_enabled =
+      ProcessTools.createJavaProcessBuilder("-XX:+PrintGCDetails", "-XX:+PrintReferenceGC", "-Xmx10M", GCTest.class.getName());
+    OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start());
+
+    String countRegex = "[0-9]+ refs";
+    String timeRegex = "[0-9]+[.,][0-9]+ secs";
+
+    output.shouldMatch(
+      "#[0-9]+: \\[SoftReference, " + countRegex + ", " + timeRegex + "\\]" +
+      "#[0-9]+: \\[WeakReference, " + countRegex + ", " + timeRegex + "\\]" +
+      "#[0-9]+: \\[FinalReference, " + countRegex + ", " + timeRegex + "\\]" +
+      "#[0-9]+: \\[PhantomReference, " + countRegex + ", " + timeRegex + "\\]" +
+      "#[0-9]+: \\[JNI Weak Reference, (" + countRegex + ", )?" + timeRegex + "\\]");
+
+    output.shouldHaveExitValue(0);
+  }
+
+  static class GCTest {
+    public static void main(String [] args) {
+      System.gc();
+    }
+  }
+}