8138760: [JVMCI] VM warning: Performance bug: SystemDictionary lookup_count=21831450 lookup_length=1275207287 average=58.411479 load=5.572844

Added debug details to the warning message.

Reviewed-by: dholmes, iklam, twisti

hotspot/src/share/vm/classfile/dictionary.cpp

@@ -396,14 +396,15 @@ void Dictionary::add_klass(Symbol* class_name, ClassLoaderData* loader_data,
 DictionaryEntry* Dictionary::get_entry(int index, unsigned int hash,
                                        Symbol* class_name,
                                        ClassLoaderData* loader_data) {
-  debug_only(_lookup_count++);
+  DEBUG_ONLY(_lookup_count++);
   for (DictionaryEntry* entry = bucket(index);
                         entry != NULL;
                         entry = entry->next()) {
     if (entry->hash() == hash && entry->equals(class_name, loader_data)) {
+      DEBUG_ONLY(bucket_count_hit(index));
       return entry;
     }
-    debug_only(_lookup_length++);
+    DEBUG_ONLY(_lookup_length++);
   }
   return NULL;
 }
@@ -596,7 +597,7 @@ void ProtectionDomainCacheTable::verify() {
   }
   guarantee(number_of_entries() == element_count,
             "Verify of protection domain cache table failed");
-  debug_only(verify_lookup_length((double)number_of_entries() / table_size()));
+  DEBUG_ONLY(verify_lookup_length((double)number_of_entries() / table_size()));
 }
 
 void ProtectionDomainCacheEntry::verify() {
@@ -737,19 +738,65 @@ void Dictionary::print(bool details) {
                    table_size(), number_of_entries());
     tty->print_cr("^ indicates that initiating loader is different from "
                   "defining loader");
+    tty->print_cr("1st number: th bucket index");
+    tty->print_cr("2nd number: the entry's index within this bucket");
+#ifdef ASSERT
+    tty->print_cr("3rd number: the hit percentage of this entry");
+    tty->print_cr("4th number: the hash index of this entry");
+#endif
   }
 
+#ifdef ASSERT
+  // find top buckets with highest lookup count
+  #define TOP_COUNT 16
+  int topItemsIndicies[TOP_COUNT];
+  for (int i = 0; i < TOP_COUNT; i++) {
+    topItemsIndicies[i] = i;
+  }
+  double total = 0.0;
+  for (int i = 0; i < table_size(); i++) {
+    // find the total count number, so later on we can
+    // express bucket lookup count as a percentage of all lookups
+    unsigned value = bucket_hits(i);
+    total += value;
+
+    // find the entry with min value
+    int index = 0;
+    unsigned min = bucket_hits(topItemsIndicies[index]);
+    for (int j = 1; j < TOP_COUNT; j++) {
+      if (bucket_hits(topItemsIndicies[j]) < min) {
+        min = bucket_hits(topItemsIndicies[j]);
+        index = j;
+      }
+    }
+    // if the bucket loookup value is bigger than the current min
+    // move that bucket index into the top list
+    if (value > min) {
+      topItemsIndicies[index] = i;
+    }
+  }
+#endif
+
   for (int index = 0; index < table_size(); index++) {
+#ifdef ASSERT
+    double percentage = 100.0 * (double)bucket_hits(index)/total;
+#endif
+    int chain = 0;
     for (DictionaryEntry* probe = bucket(index);
                           probe != NULL;
                           probe = probe->next()) {
-      if (Verbose) tty->print("%4d: ", index);
       Klass* e = probe->klass();
       ClassLoaderData* loader_data =  probe->loader_data();
       bool is_defining_class =
          (loader_data == e->class_loader_data());
+      if (details) {
+        tty->print("%4d: %3d: ", index, chain);
+#ifdef ASSERT
+        tty->print("%5.2f%%: %10u:", percentage, probe->hash());
+#endif
+      }
       tty->print("%s%s", ((!details) || is_defining_class) ? " " : "^",
-                   e->external_name());
+                 e->external_name());
 
       if (details) {
         tty->print(", loader ");
@@ -760,9 +807,30 @@ void Dictionary::print(bool details) {
         }
       }
       tty->cr();
+
+      chain++;
+    }
+    if (details && (chain == 0)) {
+      tty->print("%4d:", index);
+      tty->cr();
     }
   }
 
+#ifdef ASSERT
+  // print out the TOP_COUNT of buckets with highest lookup count (unsorted)
+  if (details) {
+    tty->cr();
+    tty->print("Top %d buckets:", TOP_COUNT);
+    tty->cr();
+    for (int i = 0; i < TOP_COUNT; i++) {
+      tty->print("%4d: hits %5.2f%%",
+                 topItemsIndicies[i],
+                 100.0*(double)bucket_hits(topItemsIndicies[i])/total);
+      tty->cr();
+    }
+  }
+#endif
+
   if (details) {
     tty->cr();
     _pd_cache_table->print();
@@ -795,7 +863,7 @@ void Dictionary::verify() {
   }
   guarantee(number_of_entries() == element_count,
             "Verify of system dictionary failed");
-  debug_only(verify_lookup_length((double)number_of_entries() / table_size()));
+  DEBUG_ONLY(if (!verify_lookup_length((double)number_of_entries() / table_size())) this->print(true));
 
   _pd_cache_table->verify();
 }

hotspot/src/share/vm/utilities/hashtable.cpp

@@ -342,13 +342,18 @@ template <MEMFLAGS F> void BasicHashtable<F>::verify() {
 
 #ifdef ASSERT
 
-template <MEMFLAGS F> void BasicHashtable<F>::verify_lookup_length(double load) {
-  if ((double)_lookup_length / (double)_lookup_count > load * 2.0) {
+template <MEMFLAGS F> bool BasicHashtable<F>::verify_lookup_length(double load) {
+  if ((!_lookup_warning) && (_lookup_count != 0)
+      && ((double)_lookup_length / (double)_lookup_count > load * 2.0)) {
     warning("Performance bug: SystemDictionary lookup_count=%d "
             "lookup_length=%d average=%lf load=%f",
             _lookup_count, _lookup_length,
-            (double) _lookup_length / _lookup_count, load);
+            (double)_lookup_length / _lookup_count, load);
+    _lookup_warning = true;
+
+    return false;
   }
+  return true;
 }
 
 #endif

hotspot/src/share/vm/utilities/hashtable.hpp

@@ -124,9 +124,17 @@ private:
   // Instance variable
   BasicHashtableEntry<F>*       _entry;
 
+#ifdef ASSERT
+private:
+  unsigned _hits;
+public:
+  unsigned hits()   { return _hits; }
+  void count_hit()  { _hits++; }
+#endif
+
 public:
   // Accessing
-  void clear()                        { _entry = NULL; }
+  void clear()                        { _entry = NULL; DEBUG_ONLY(_hits = 0); }
 
   // The following methods use order access methods to avoid race
   // conditions in multiprocessor systems.
@@ -135,6 +143,7 @@ public:
 
   // The following method is not MT-safe and must be done under lock.
   BasicHashtableEntry<F>** entry_addr()  { return &_entry; }
+
 };
 
 
@@ -173,9 +182,10 @@ private:
 protected:
 
 #ifdef ASSERT
+  bool              _lookup_warning;
   mutable int       _lookup_count;
   mutable int       _lookup_length;
-  void verify_lookup_length(double load);
+  bool verify_lookup_length(double load);
 #endif
 
   void initialize(int table_size, int entry_size, int number_of_entries);
@@ -226,6 +236,15 @@ public:
   int number_of_entries() { return _number_of_entries; }
 
   void verify() PRODUCT_RETURN;
+
+#ifdef ASSERT
+  void bucket_count_hit(int i) const {
+    _buckets[i].count_hit();
+  }
+  unsigned bucket_hits(int i) const {
+    return _buckets[i].hits();
+  }
+#endif
 };
 
 

hotspot/src/share/vm/utilities/hashtable.inline.hpp

@@ -65,6 +65,7 @@ template <MEMFLAGS F> inline void BasicHashtable<F>::initialize(int table_size,
   _end_block = NULL;
   _number_of_entries = number_of_entries;
 #ifdef ASSERT
+  _lookup_warning = false;
   _lookup_count = 0;
   _lookup_length = 0;
 #endif