8133818: Additional number of processed references printed with -XX:+PrintReferenceGC after JDK-8047125

Test contributed by brutisso

Reviewed-by: tonyp, tschatzl

hotspot/src/share/vm/gc/shared/gcTrace.cpp

@@ -88,6 +88,8 @@ void GCTracer::report_gc_reference_stats(const ReferenceProcessorStats& rps) con
   send_reference_stats_event(REF_WEAK, rps.weak_count());
   send_reference_stats_event(REF_FINAL, rps.final_count());
   send_reference_stats_event(REF_PHANTOM, rps.phantom_count());
+  send_reference_stats_event(REF_CLEANER, rps.cleaner_count());
+  send_reference_stats_event(REF_JNI, rps.jni_weak_ref_count());
 }
 
 #if INCLUDE_SERVICES

hotspot/src/share/vm/gc/shared/referenceProcessor.cpp

@@ -243,10 +243,13 @@ ReferenceProcessorStats ReferenceProcessor::process_discovered_references(
       process_discovered_reflist(_discoveredPhantomRefs, NULL, false,
                                  is_alive, keep_alive, complete_gc, task_executor);
 
-    // Process cleaners, but include them 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.
-    phantom_count +=
+  }
+
+  // Cleaners
+  size_t cleaner_count = 0;
+  {
+    GCTraceTime tt("Cleaners", trace_time, false, gc_timer, gc_id);
+    cleaner_count =
       process_discovered_reflist(_discoveredCleanerRefs, NULL, true,
                                  is_alive, keep_alive, complete_gc, task_executor);
   }
@@ -256,15 +259,17 @@ ReferenceProcessorStats ReferenceProcessor::process_discovered_references(
   // that is not how the JDK1.2 specification is. See #4126360. Native code can
   // thus use JNI weak references to circumvent the phantom references and
   // resurrect a "post-mortem" object.
+  size_t jni_weak_ref_count = 0;
   {
     GCTraceTime tt("JNI Weak Reference", trace_time, false, gc_timer, gc_id);
     if (task_executor != NULL) {
       task_executor->set_single_threaded_mode();
     }
-    process_phaseJNI(is_alive, keep_alive, complete_gc);
+    jni_weak_ref_count =
+      process_phaseJNI(is_alive, keep_alive, complete_gc);
   }
 
-  return ReferenceProcessorStats(soft_count, weak_count, final_count, phantom_count);
+  return ReferenceProcessorStats(soft_count, weak_count, final_count, phantom_count, cleaner_count, jni_weak_ref_count);
 }
 
 #ifndef PRODUCT
@@ -291,17 +296,17 @@ uint ReferenceProcessor::count_jni_refs() {
 }
 #endif
 
-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);
+size_t ReferenceProcessor::process_phaseJNI(BoolObjectClosure* is_alive,
+                                            OopClosure*        keep_alive,
+                                            VoidClosure*       complete_gc) {
+  DEBUG_ONLY(size_t check_count = count_jni_refs();)
+  size_t count = JNIHandles::weak_oops_do(is_alive, keep_alive);
+  assert(count == check_count, "Counts didn't match");
   complete_gc->do_void();
+  if (PrintGCDetails && PrintReferenceGC) {
+    gclog_or_tty->print(", " SIZE_FORMAT " refs", count);
+  }
+  return count;
 }
 
 
@@ -941,9 +946,10 @@ inline DiscoveredList* ReferenceProcessor::get_discovered_list(ReferenceType rt)
       list = &_discoveredCleanerRefs[id];
       break;
     case REF_NONE:
+    case REF_JNI:
       // we should not reach here if we are an InstanceRefKlass
     default:
-      ShouldNotReachHere();
+      guarantee(false, err_msg("rt should not be %d", rt));
   }
   if (TraceReferenceGC && PrintGCDetails) {
     gclog_or_tty->print_cr("Thread %d gets list " INTPTR_FORMAT, id, p2i(list));

hotspot/src/share/vm/gc/shared/referenceProcessor.hpp

@@ -247,7 +247,7 @@ class ReferenceProcessor : public CHeapObj<mtGC> {
   DiscoveredList* _discoveredCleanerRefs;
 
  public:
-  static int number_of_subclasses_of_ref() { return (REF_CLEANER - REF_OTHER); }
+  static int number_of_subclasses_of_ref() { return REF_LISTS_COUNT; }
 
   uint num_q()                             { return _num_q; }
   uint max_num_q()                         { return _max_num_q; }
@@ -271,9 +271,9 @@ class ReferenceProcessor : public CHeapObj<mtGC> {
                                     VoidClosure*                 complete_gc,
                                     AbstractRefProcTaskExecutor* task_executor);
 
-  void process_phaseJNI(BoolObjectClosure* is_alive,
-                        OopClosure*        keep_alive,
-                        VoidClosure*       complete_gc);
+  size_t process_phaseJNI(BoolObjectClosure* is_alive,
+                          OopClosure*        keep_alive,
+                          VoidClosure*       complete_gc);
 
   // Work methods used by the method process_discovered_reflist
   // Phase1: keep alive all those referents that are otherwise

hotspot/src/share/vm/gc/shared/referenceProcessorStats.hpp

@@ -36,22 +36,30 @@ class ReferenceProcessorStats {
   size_t _weak_count;
   size_t _final_count;
   size_t _phantom_count;
+  size_t _cleaner_count;
+  size_t _jni_weak_ref_count;
 
  public:
   ReferenceProcessorStats() :
     _soft_count(0),
     _weak_count(0),
     _final_count(0),
-    _phantom_count(0) {}
+    _phantom_count(0),
+    _cleaner_count(0),
+    _jni_weak_ref_count(0) {}
 
   ReferenceProcessorStats(size_t soft_count,
                           size_t weak_count,
                           size_t final_count,
-                          size_t phantom_count) :
+                          size_t phantom_count,
+                          size_t cleaner_count,
+                          size_t jni_weak_ref_count) :
     _soft_count(soft_count),
     _weak_count(weak_count),
     _final_count(final_count),
-    _phantom_count(phantom_count)
+    _phantom_count(phantom_count),
+    _cleaner_count(cleaner_count),
+    _jni_weak_ref_count(jni_weak_ref_count)
   {}
 
   size_t soft_count() const {
@@ -69,5 +77,13 @@ class ReferenceProcessorStats {
   size_t phantom_count() const {
     return _phantom_count;
   }
+
+  size_t cleaner_count() const {
+    return _cleaner_count;
+  }
+
+  size_t jni_weak_ref_count() const {
+    return _jni_weak_ref_count;
+  }
 };
 #endif

hotspot/src/share/vm/memory/referenceType.hpp

@@ -32,11 +32,15 @@
 enum ReferenceType {
   REF_NONE,      // Regular class
   REF_OTHER,     // Subclass of java/lang/ref/Reference, but not subclass of one of the classes below
+  ///////////////// Only the types below have their own discovered lists
   REF_SOFT,      // Subclass of java/lang/ref/SoftReference
   REF_WEAK,      // Subclass of java/lang/ref/WeakReference
   REF_FINAL,     // Subclass of java/lang/ref/FinalReference
   REF_PHANTOM,   // Subclass of java/lang/ref/PhantomReference
-  REF_CLEANER    // Subclass of sun/misc/Cleaner
+  REF_CLEANER,   // Subclass of sun/misc/Cleaner
+  ///////////////// Only the types in the above range have their own discovered lists
+  REF_JNI,        // JNI weak refs
+  REF_LISTS_COUNT = REF_CLEANER - REF_OTHER  // Number of discovered lists
 };
 
 #endif // SHARE_VM_MEMORY_REFERENCETYPE_HPP

hotspot/src/share/vm/prims/jvmtiExport.cpp

@@ -2181,8 +2181,8 @@ void JvmtiExport::oops_do(OopClosure* f) {
   JvmtiVMObjectAllocEventCollector::oops_do_for_all_threads(f);
 }
 
-void JvmtiExport::weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f) {
-  JvmtiTagMap::weak_oops_do(is_alive, f);
+size_t JvmtiExport::weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f) {
+  return JvmtiTagMap::weak_oops_do(is_alive, f);
 }
 
 void JvmtiExport::gc_epilogue() {

hotspot/src/share/vm/prims/jvmtiExport.hpp

@@ -366,7 +366,7 @@ class JvmtiExport : public AllStatic {
   static void clear_detected_exception   (JavaThread* thread) NOT_JVMTI_RETURN;
 
   static void oops_do(OopClosure* f) NOT_JVMTI_RETURN;
-  static void weak_oops_do(BoolObjectClosure* b, OopClosure* f) NOT_JVMTI_RETURN;
+  static size_t weak_oops_do(BoolObjectClosure* b, OopClosure* f) NOT_JVMTI_RETURN_(0);
   static void gc_epilogue() NOT_JVMTI_RETURN;
 
   static void transition_pending_onload_raw_monitors() NOT_JVMTI_RETURN;

hotspot/src/share/vm/prims/jvmtiTagMap.cpp

@@ -3284,32 +3284,35 @@ void JvmtiTagMap::follow_references(jint heap_filter,
 }
 
 
-void JvmtiTagMap::weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f) {
+size_t JvmtiTagMap::weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f) {
   // No locks during VM bring-up (0 threads) and no safepoints after main
   // thread creation and before VMThread creation (1 thread); initial GC
   // verification can happen in that window which gets to here.
   assert(Threads::number_of_threads() <= 1 ||
          SafepointSynchronize::is_at_safepoint(),
          "must be executed at a safepoint");
+  size_t count = 0;
   if (JvmtiEnv::environments_might_exist()) {
     JvmtiEnvIterator it;
     for (JvmtiEnvBase* env = it.first(); env != NULL; env = it.next(env)) {
       JvmtiTagMap* tag_map = env->tag_map();
       if (tag_map != NULL && !tag_map->is_empty()) {
-        tag_map->do_weak_oops(is_alive, f);
+        count += tag_map->do_weak_oops(is_alive, f);
       }
     }
   }
+  return count;
 }
 
-void JvmtiTagMap::do_weak_oops(BoolObjectClosure* is_alive, OopClosure* f) {
+size_t JvmtiTagMap::do_weak_oops(BoolObjectClosure* is_alive, OopClosure* f) {
 
   // does this environment have the OBJECT_FREE event enabled
   bool post_object_free = env()->is_enabled(JVMTI_EVENT_OBJECT_FREE);
 
   // counters used for trace message
-  int freed = 0;
-  int moved = 0;
+  size_t freed = 0;
+  size_t moved = 0;
+  size_t stayed = 0;
 
   JvmtiTagHashmap* hashmap = this->hashmap();
 
@@ -3318,7 +3321,7 @@ void JvmtiTagMap::do_weak_oops(BoolObjectClosure* is_alive, OopClosure* f) {
 
   // if the hashmap is empty then we can skip it
   if (hashmap->_entry_count == 0) {
-    return;
+    return 0;
   }
 
   // now iterate through each entry in the table
@@ -3380,6 +3383,7 @@ void JvmtiTagMap::do_weak_oops(BoolObjectClosure* is_alive, OopClosure* f) {
         } else {
           // object didn't move
           prev = entry;
+          stayed++;
         }
       }
 
@@ -3398,10 +3402,12 @@ void JvmtiTagMap::do_weak_oops(BoolObjectClosure* is_alive, OopClosure* f) {
 
   // stats
   if (TraceJVMTIObjectTagging) {
-    int post_total = hashmap->_entry_count;
-    int pre_total = post_total + freed;
+    size_t post_total = hashmap->_entry_count;
+    size_t pre_total = post_total + freed;
 
-    tty->print_cr("(%d->%d, %d freed, %d total moves)",
-        pre_total, post_total, freed, moved);
+    tty->print_cr("(" SIZE_FORMAT "->" SIZE_FORMAT ", " SIZE_FORMAT " freed, " SIZE_FORMAT " stayed, " SIZE_FORMAT " moved)",
+        pre_total, post_total, freed, stayed, moved);
   }
+
+  return (freed + stayed + moved);
 }

hotspot/src/share/vm/prims/jvmtiTagMap.hpp

@@ -60,7 +60,7 @@ class JvmtiTagMap :  public CHeapObj<mtInternal> {
   inline Mutex* lock()                      { return &_lock; }
   inline JvmtiEnv* env() const              { return _env; }
 
-  void do_weak_oops(BoolObjectClosure* is_alive, OopClosure* f);
+  size_t do_weak_oops(BoolObjectClosure* is_alive, OopClosure* f);
 
   // iterate over all entries in this tag map
   void entry_iterate(JvmtiTagHashmapEntryClosure* closure);
@@ -122,8 +122,8 @@ class JvmtiTagMap :  public CHeapObj<mtInternal> {
                                    jint* count_ptr, jobject** object_result_ptr,
                                    jlong** tag_result_ptr);
 
-  static void weak_oops_do(
-      BoolObjectClosure* is_alive, OopClosure* f) NOT_JVMTI_RETURN;
+  static size_t weak_oops_do(BoolObjectClosure* is_alive,
+                             OopClosure* f) NOT_JVMTI_RETURN_(0);
 };
 
 #endif // SHARE_VM_PRIMS_JVMTITAGMAP_HPP

hotspot/src/share/vm/runtime/jniHandles.cpp

@@ -124,8 +124,8 @@ void JNIHandles::oops_do(OopClosure* f) {
 }
 
 
-void JNIHandles::weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f) {
-  _weak_global_handles->weak_oops_do(is_alive, f);
+size_t JNIHandles::weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f) {
+  return _weak_global_handles->weak_oops_do(is_alive, f);
 }
 
 
@@ -380,8 +380,9 @@ void JNIHandleBlock::oops_do(OopClosure* f) {
 }
 
 
-void JNIHandleBlock::weak_oops_do(BoolObjectClosure* is_alive,
-                                  OopClosure* f) {
+size_t JNIHandleBlock::weak_oops_do(BoolObjectClosure* is_alive,
+                                    OopClosure* f) {
+  size_t count = 0;
   for (JNIHandleBlock* current = this; current != NULL; current = current->_next) {
     assert(current->pop_frame_link() == NULL,
       "blocks holding weak global JNI handles should not have pop frame link set");
@@ -390,6 +391,7 @@ void JNIHandleBlock::weak_oops_do(BoolObjectClosure* is_alive,
       oop value = *root;
       // traverse heap pointers only, not deleted handles or free list pointers
       if (value != NULL && Universe::heap()->is_in_reserved(value)) {
+        count++;
         if (is_alive->do_object_b(value)) {
           // The weakly referenced object is alive, update pointer
           f->do_oop(root);
@@ -412,7 +414,9 @@ void JNIHandleBlock::weak_oops_do(BoolObjectClosure* is_alive,
    * JVMTI data structures may also contain weak oops.  The iteration of them
    * is placed here so that we don't need to add it to each of the collectors.
    */
-  JvmtiExport::weak_oops_do(is_alive, f);
+  count += JvmtiExport::weak_oops_do(is_alive, f);
+
+  return count;
 }
 
 

hotspot/src/share/vm/runtime/jniHandles.hpp

@@ -85,7 +85,7 @@ class JNIHandles : AllStatic {
   // Traversal of regular global handles
   static void oops_do(OopClosure* f);
   // Traversal of weak global handles. Unreachable oops are cleared.
-  static void weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f);
+  static size_t weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f);
 };
 
 
@@ -153,7 +153,7 @@ class JNIHandleBlock : public CHeapObj<mtInternal> {
   // Traversal of regular handles
   void oops_do(OopClosure* f);
   // Traversal of weak handles. Unreachable oops are cleared.
-  void weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f);
+  size_t weak_oops_do(BoolObjectClosure* is_alive, OopClosure* f);
 
   // Checked JNI support
   void set_planned_capacity(size_t planned_capacity) { _planned_capacity = planned_capacity; }

hotspot/test/gc/logging/TestPrintReferences.java

@@ -0,0 +1,59 @@
+/*
+ * 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 8133818
+ * @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());
+
+    output.shouldMatch(
+      "#[0-9]+: \\[SoftReference, [0-9]+ refs, [0-9]+\\.[0-9]+ secs\\]" +
+      "#[0-9]+: \\[WeakReference, [0-9]+ refs, [0-9]+\\.[0-9]+ secs\\]" +
+      "#[0-9]+: \\[FinalReference, [0-9]+ refs, [0-9]+\\.[0-9]+ secs\\]" +
+      "#[0-9]+: \\[PhantomReference, [0-9]+ refs, [0-9]+\\.[0-9]+ secs\\]" +
+      "#[0-9]+: \\[Cleaners, [0-9]+ refs, [0-9]+\\.[0-9]+ secs\\]" +
+      "#[0-9]+: \\[JNI Weak Reference, [0-9]+ refs, [0-9]+\\.[0-9]+ secs\\]");
+
+    output.shouldHaveExitValue(0);
+  }
+
+  static class GCTest {
+    public static void main(String [] args) {
+      System.gc();
+    }
+  }
+}