JDK-8138760 : [JVMCI] VM warning: Performance bug: SystemDictionary lookup_count=21831450 lookup_length=1275207287 average=58.411479 load=5.572844
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 9
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2015-10-02
  • Updated: 2017-05-16
  • Resolved: 2016-07-19
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9 b131Fixed
Related Reports
Relates :  
JDK-8166848 - Performance bug: SystemDictionary - optimization
Relates :  
JDK-8166145 - runtime/threads/ThreadInterruptTest3 fails with ExitCode 0
Relates :  
JDK-8166295 - [TESTBUG] nsk/regression/b4318701 b4324656 b4330134 fail with exit code 97
Relates :  
JDK-8160577 - verify_lookup_length is defined and implemented in BasicHashtable, but only used by SharedDictionary
Description
Java HotSpot(TM) Client VM warning: Performance bug: SystemDictionary lookup_count=21831450 lookup_length=1275207287 average=58.411479 load=5.572844

I've never seen such warning before, and not sure that it relates to jvmci, but it happened in jvmci PIT, so targeting it to hs/compiler
Comments
That the lookup_count is less than the lookup_length (I was wrong before), means that most of the lookups are not in the first bucket entry. The hashtable is too full in this case. DictionaryEntry* Dictionary::get_entry(int index, unsigned int hash, Symbol* class_name, ClassLoaderData* loader_data) { 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++); } return NULL; } Note that this function is called without a lock and there's no atomic accesses to the count, but the count is probably reasonable accurate. This warning is useless though. It may have been added during development to indicate that the System dictionary elements should implement some sort of reshuffling algorithm for the buckets. There really isn't anything that we can do with this warning other than increase the size of the table, which this load_factor: elements/size_of_table being 5 doesn't seem very much out of wack. Knowing the longest bucket size for determining whether the hash function is good or not would be more useful, but bucket_hits only returns how many times the entry is found in the bucket. Not that useful either. In this case, if we had resizing, reversing the bucket order might help this, but I think the resizing heuristic wouldn't be this calculation either.
16-05-2017
FC Extension Request Remaining work: Change is implemented, testing and review is complete. Risk level: Minimal risk - only affects debug build and we only change a debug message with minimal supporting code. Justification: Adding it as part of jdk9 will allow us to receive more reports with detailed info that will allow us to address the issue better. Feature complete: Already complete.
18-07-2016
To answer the original question here as to what the warning means: The current understanding is that there is a ���potential��� problem with performance��accessing SD, where our heuristic indicates that the average lookup factor is too high relative to the table���s actual load��factor. Furthermore, Ioi has a working theory that what is responsible for that high average lookup factor is that ���java.lang.Object��� is at the end of the chain��and gets looked up frequently.
14-07-2016
[~gziemski] the output looks good. When the bug happens with kitchensink, we should see some bucket(s) with a very large number of entries. Meaning of "average=58.411479 load=5.572844" -- Every lookup has scanned 58.41 entries. However, on average, each bucket has only 5.57 entries.
30-06-2016
Added hashes and bucket/chain info to the table printing, like so: Java system dictionary (table_size=1009, classes=485) ^ indicates that initiating loader is different from defining loader [ 0, 0] [ 1, 0] [ 2, 0] [ 3, 0] [ 4, 0] java.lang.reflect.Layer [369436273], loader NULL class_loader [ 4, 1] java.lang.System [509845686], loader NULL class_loader [ 5, 0] ... [ 998, 0] [ 999, 0] java.util.Collections$UnmodifiableCollection$1 [1207353246], loader NULL class_loader [1000, 0] java.lang.ref.FinalReference [309368472], loader NULL class_loader [1001, 0] jdk.internal.module.ModuleBootstrap [567622023], loader NULL class_loader [1001, 1] java.lang.StackWalker [467546376], loader NULL class_loader [1002, 0] sun.nio.cs.UTF_16BE [428929929], loader NULL class_loader [1003, 0] [1004, 0] [1005, 0] [1006, 0] [1007, 0] java.nio.file.CopyOption [1988414100], loader NULL class_loader [1008, 0] [~iklam] Ioi, is this enough info in the table for you to draw more conclusions, when we get the report back?
30-06-2016
Printing the dictionary doesn't appear all that useful, i.e.: Java system dictionary (table_size=1009, classes=485) ^ indicates that initiating loader is different from defining loader java.lang.Runnable, loader NULL class_loader java.lang.InterruptedException, loader NULL class_loader java.lang.Throwable, loader NULL class_loader ... java.lang.invoke.CallSite, loader NULL class_loader java.lang.ThreadLocal$ThreadLocalMap, loader NULL class_loader Protection domain cache table (table_size=2017, classes=1) entry 0x00007f82c7028c20 value 0x00000006cfe209c0 strongly_reachable 0 next 0x0000000000000000 Nothing here that would lead us to conclude much more than we need to increase the table size. We may need to collect some basic stats, but even with more details/stats all we can probably do is to conclude that we need to increase the table size (all change the hash code)
30-06-2016
"verify_lookup_length" is defined in BasicHashtable<F>, and it's called by "verify()" methods in: ProtectionDomainCacheTable : Hashtable : BasicHashtable Dictionary : TwoOopHashtable : Hashtable : BasicHashtable SymbolEntryTable : Hashtable : BasicHashtable ModuleEntryTable : Hashtable : BasicHashtable PackageEntryTable : Hashtable : BasicHashtable PlaceholderTable : TwoOopHashtable : Hashtable : BasicHashtable where "SharedDictionary" is the only class extending "Dictionary". "verify_lookup_length" uses "_lookup_count" and "_lookup_length" fields defined in BasicHashtable<F>, but the only class actually using those fields is "SharedDictionary", in all other cases they are not used, so "verify_lookup_length is a NOP for all the cases except "SharedDictionary". This should be cleaned up by a follow up issue JDK-8160577
29-06-2016
Causing an assert would result in a coredump file, which will allow us to understand what's inside the dictionary. Alternatively, on the first time such a warning is printed, if in a debug build, print out the entire system dictionary with the hashcode of each item.
28-06-2016
I'm not sure just changing "warning" into "assert" to see where it happens would help much, because the "verify_lookup_length " method is only called from "Dictionary::verify()", ex: Thread 15 Crashed:: Java: VM Thread 0 libsystem_kernel.dylib 0x00007fff9b312f06 __pthread_kill + 10 1 libsystem_pthread.dylib 0x00007fff91b4e4ec pthread_kill + 90 2 libsystem_c.dylib 0x00007fff9d3b26e7 abort + 129 3 libjvm.dylib 0x000000010283c037 os::abort(bool, void*, void const*) + 167 (os_bsd.cpp:1119) 4 libjvm.dylib 0x0000000101fadac3 VMError::report_and_die(int, char const*, char const*, __va_list_tag*, Thread*, unsigned char*, void*, void*, char const*, int, unsigned long) + 2627 (vmError.cpp:1340) 5 libjvm.dylib 0x0000000101fadbc8 VMError::report_and_die(Thread*, char const*, int, char const*, char const*, __va_list_tag*) + 120 (vmError.cpp:1106) 6 libjvm.dylib 0x0000000101f7cc6f report_vm_error(char const*, int, char const*, char const*, ...) + 415 (debug.cpp:220) 7 libjvm.dylib 0x0000000101f99de8 BasicHashtable<(MemoryType)1>::verify_lookup_length(double) + 184 (hashtable.cpp:352) 8 libjvm.dylib 0x000000010250300f Dictionary::verify() + 687 (dictionary.cpp:800) 9 libjvm.dylib 0x000000010254083a SystemDictionary::verify() + 234 (systemDictionary.cpp:2900) 10 libjvm.dylib 0x00000001024b6eb6 Universe::verify(VerifyOption, char const*) + 694 (universe.cpp:1195) 11 libjvm.dylib 0x0000000101ef74f9 Universe::verify(char const*) + 25 (universe.hpp:493) 12 libjvm.dylib 0x0000000101ef6b00 Universe::verify() + 16 (universe.hpp:496) 13 libjvm.dylib 0x0000000102427172 VMThread::run() + 578 (vmThread.cpp:285) 14 libjvm.dylib 0x000000010283b4cc thread_native_entry(Thread*) + 396 (os_bsd.cpp:721) 15 libsystem_pthread.dylib 0x00007fff91b4b99d _pthread_body + 131 16 libsystem_pthread.dylib 0x00007fff91b4b91a _pthread_start + 168 17 libsystem_pthread.dylib 0x00007fff91b49351 thread_start + 13 so showing this back trace is not that interesting. We should probably keep it as a warning, but add a comment suggesting how to fix it, ie. Increase the dictionary size. We could also print the table info (statistics) to help the user figure out what is going on.
28-06-2016
I'm assigning this to runtime to maybe add the assert that [~iklam] is suggesting.
18-11-2015
This probably means one (or several) of the chains in the system dictionary is excessively long, AND this chain has been repeatedly looked up. Maybe it's the chain that contains a popular base class like java.lang.Object? It's better to change the warning to an assert, so if it happens again (in a non-product build) we can have a core file to look at. Otherwise the warning is rather meaningless.
06-10-2015
Can you ask someone from the Runtime team to explain what this means?
02-10-2015