8166145: runtime/threads/ThreadInterruptTest3 fails with ExitCode 0
Summary: Added new hashtables logging tag and used it print out the table performance details.
Reviewed-by: coleenp, dholmes
--- a/hotspot/src/share/vm/classfile/dictionary.cpp Thu Oct 27 12:22:28 2016 +0200
+++ b/hotspot/src/share/vm/classfile/dictionary.cpp Thu Oct 27 09:42:45 2016 -0500
@@ -597,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(), "Domain Cache Table"));
}
void ProtectionDomainCacheEntry::verify() {
@@ -738,50 +738,9 @@
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()) {
@@ -790,10 +749,7 @@
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("%4d: ", index);
}
tty->print("%s%s", ((!details) || is_defining_class) ? " " : "^",
e->external_name());
@@ -807,30 +763,9 @@
}
}
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();
@@ -838,6 +773,84 @@
tty->cr();
}
+#ifdef ASSERT
+void Dictionary::printPerformanceInfoDetails() {
+ if (log_is_enabled(Info, hashtables)) {
+ ResourceMark rm;
+ HandleMark hm;
+
+ log_info(hashtables)(" ");
+ log_info(hashtables)("Java system dictionary (table_size=%d, classes=%d)",
+ table_size(), number_of_entries());
+ log_info(hashtables)("1st number: the bucket index");
+ log_info(hashtables)("2nd number: the hit percentage for this bucket");
+ log_info(hashtables)("3rd number: the entry's index within this bucket");
+ log_info(hashtables)("4th number: the hash index of this entry");
+ log_info(hashtables)(" ");
+
+ // 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 top entry with min value
+ int min_index = 0;
+ unsigned min_value = bucket_hits(topItemsIndicies[min_index]);
+ for (int j = 1; j < TOP_COUNT; j++) {
+ unsigned top_value = bucket_hits(topItemsIndicies[j]);
+ if (top_value < min_value) {
+ min_value = top_value;
+ min_index = j;
+ }
+ }
+ // if the bucket loookup value is bigger than the top buckets min
+ // move that bucket index into the top list
+ if (value > min_value) {
+ topItemsIndicies[min_index] = i;
+ }
+ }
+
+ for (int index = 0; index < table_size(); index++) {
+ double percentage = 100.0 * (double)bucket_hits(index)/total;
+ int chain = 0;
+ for (DictionaryEntry* probe = bucket(index);
+ probe != NULL;
+ probe = probe->next()) {
+ Klass* e = probe->klass();
+ ClassLoaderData* loader_data = probe->loader_data();
+ bool is_defining_class =
+ (loader_data == e->class_loader_data());
+ log_info(hashtables)("%4d: %5.2f%%: %3d: %10u: %s, loader %s",
+ index, percentage, chain, probe->hash(), e->external_name(),
+ (loader_data != NULL) ? loader_data->loader_name() : "NULL");
+
+ chain++;
+ }
+ if (chain == 0) {
+ log_info(hashtables)("%4d:", index+1);
+ }
+ }
+ log_info(hashtables)(" ");
+
+ // print out the TOP_COUNT of buckets with highest lookup count (unsorted)
+ log_info(hashtables)("Top %d buckets:", TOP_COUNT);
+ for (int i = 0; i < TOP_COUNT; i++) {
+ log_info(hashtables)("%4d: hits %5.2f%%",
+ topItemsIndicies[i],
+ 100.0*(double)bucket_hits(topItemsIndicies[i])/total);
+ }
+ }
+}
+#endif // ASSERT
+
void Dictionary::verify() {
guarantee(number_of_entries() >= 0, "Verify of system dictionary failed");
@@ -863,7 +876,11 @@
}
guarantee(number_of_entries() == element_count,
"Verify of system dictionary failed");
- DEBUG_ONLY(if (!verify_lookup_length((double)number_of_entries() / table_size())) this->print(true));
+#ifdef ASSERT
+ if (!verify_lookup_length((double)number_of_entries() / table_size(), "System Dictionary")) {
+ this->printPerformanceInfoDetails();
+ }
+#endif // ASSERT
_pd_cache_table->verify();
}
--- a/hotspot/src/share/vm/classfile/dictionary.hpp Thu Oct 27 12:22:28 2016 +0200
+++ b/hotspot/src/share/vm/classfile/dictionary.hpp Thu Oct 27 09:42:45 2016 -0500
@@ -131,6 +131,9 @@
ProtectionDomainCacheEntry* cache_get(oop protection_domain);
void print(bool details = true);
+#ifdef ASSERT
+ void printPerformanceInfoDetails();
+#endif // ASSERT
void verify();
};
--- a/hotspot/src/share/vm/classfile/moduleEntry.cpp Thu Oct 27 12:22:28 2016 +0200
+++ b/hotspot/src/share/vm/classfile/moduleEntry.cpp Thu Oct 27 09:42:45 2016 -0500
@@ -440,7 +440,7 @@
}
guarantee(number_of_entries() == element_count,
"Verify of Module Entry Table failed");
- debug_only(verify_lookup_length((double)number_of_entries() / table_size()));
+ DEBUG_ONLY(verify_lookup_length((double)number_of_entries() / table_size(), "Module Entry Table"));
}
void ModuleEntry::verify() {
--- a/hotspot/src/share/vm/classfile/packageEntry.cpp Thu Oct 27 12:22:28 2016 +0200
+++ b/hotspot/src/share/vm/classfile/packageEntry.cpp Thu Oct 27 09:42:45 2016 -0500
@@ -365,7 +365,7 @@
}
guarantee(number_of_entries() == element_count,
"Verify of Package Entry Table failed");
- debug_only(verify_lookup_length((double)number_of_entries() / table_size()));
+ DEBUG_ONLY(verify_lookup_length((double)number_of_entries() / table_size(), "Package Entry Table"));
}
void PackageEntry::verify() {
--- a/hotspot/src/share/vm/logging/logTag.hpp Thu Oct 27 12:22:28 2016 +0200
+++ b/hotspot/src/share/vm/logging/logTag.hpp Thu Oct 27 09:42:45 2016 -0500
@@ -61,6 +61,7 @@
LOG_TAG(exit) \
LOG_TAG(freelist) \
LOG_TAG(gc) \
+ LOG_TAG(hashtables) \
LOG_TAG(heap) \
LOG_TAG(humongous) \
LOG_TAG(ihop) \
--- a/hotspot/src/share/vm/utilities/hashtable.cpp Thu Oct 27 12:22:28 2016 +0200
+++ b/hotspot/src/share/vm/utilities/hashtable.cpp Thu Oct 27 09:42:45 2016 -0500
@@ -342,12 +342,12 @@
#ifdef ASSERT
-template <MEMFLAGS F> bool BasicHashtable<F>::verify_lookup_length(double load) {
+template <MEMFLAGS F> bool BasicHashtable<F>::verify_lookup_length(double load, const char *table_name) {
if ((!_lookup_warning) && (_lookup_count != 0)
&& ((double)_lookup_length / (double)_lookup_count > load * 2.0)) {
- warning("Performance bug: SystemDictionary lookup_count=%d "
+ warning("Performance bug: %s lookup_count=%d "
"lookup_length=%d average=%lf load=%f",
- _lookup_count, _lookup_length,
+ table_name, _lookup_count, _lookup_length,
(double)_lookup_length / _lookup_count, load);
_lookup_warning = true;
--- a/hotspot/src/share/vm/utilities/hashtable.hpp Thu Oct 27 12:22:28 2016 +0200
+++ b/hotspot/src/share/vm/utilities/hashtable.hpp Thu Oct 27 09:42:45 2016 -0500
@@ -1,5 +1,5 @@
/*
- * Copyright (c) 2003, 2014, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2003, 2016, 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
@@ -185,7 +185,7 @@
bool _lookup_warning;
mutable int _lookup_count;
mutable int _lookup_length;
- bool verify_lookup_length(double load);
+ bool verify_lookup_length(double load, const char *table_name);
#endif
void initialize(int table_size, int entry_size, int number_of_entries);