8138760: [JVMCI] VM warning: Performance bug: SystemDictionary lookup_count=21831450 lookup_length=1275207287 average=58.411479 load=5.572844
Summary: Added debug details to the warning message.
Reviewed-by: dholmes, iklam, twisti
--- a/hotspot/src/share/vm/classfile/dictionary.cpp Tue Jul 19 09:30:30 2016 +0200
+++ b/hotspot/src/share/vm/classfile/dictionary.cpp Tue Jul 19 11:00:45 2016 -0500
@@ -396,14 +396,15 @@
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 @@
}
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 @@
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 @@
}
}
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 @@
}
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();
}
--- a/hotspot/src/share/vm/utilities/hashtable.cpp Tue Jul 19 09:30:30 2016 +0200
+++ b/hotspot/src/share/vm/utilities/hashtable.cpp Tue Jul 19 11:00:45 2016 -0500
@@ -342,13 +342,18 @@
#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
--- a/hotspot/src/share/vm/utilities/hashtable.hpp Tue Jul 19 09:30:30 2016 +0200
+++ b/hotspot/src/share/vm/utilities/hashtable.hpp Tue Jul 19 11:00:45 2016 -0500
@@ -124,9 +124,17 @@
// 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 @@
// The following method is not MT-safe and must be done under lock.
BasicHashtableEntry<F>** entry_addr() { return &_entry; }
+
};
@@ -173,9 +182,10 @@
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 @@
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
};
--- a/hotspot/src/share/vm/utilities/hashtable.inline.hpp Tue Jul 19 09:30:30 2016 +0200
+++ b/hotspot/src/share/vm/utilities/hashtable.inline.hpp Tue Jul 19 11:00:45 2016 -0500
@@ -65,6 +65,7 @@
_end_block = NULL;
_number_of_entries = number_of_entries;
#ifdef ASSERT
+ _lookup_warning = false;
_lookup_count = 0;
_lookup_length = 0;
#endif