JDK-8195100 : Use a low latency hashtable for SymbolTable
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 11
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-01-15
  • Updated: 2024-09-05
  • Resolved: 2018-08-14
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 12
12 b07Fixed
Related Reports
Blocks :  
Blocks :  
Blocks :  
Blocks :  
Blocks :  
Blocks :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Description
SymbolTable is the data-set which can introduce the most latency for a GC.
Comments
URL: http://hg.openjdk.java.net/jdk/jdk/rev/8b23aa7cef47 User: gziemski Date: 2018-08-14 23:43:15 +0000
14-08-2018

Note to myself: what happens to dead Symbols after they are left behind when moving to a new SymbolTableHash (_local_table)?
09-08-2018

Note, without void GlobalCounter::write_synchronize() { assert((*Thread::current()->get_rcu_counter() & COUNTER_ACTIVE) == 0x0, "must be outside a critcal section"); // Atomic::add must provide fence since we have storeload dependency. volatile uintx gbl_cnt = Atomic::add((uintx)COUNTER_INCREMENT, &_global_counter._counter, memory_order_conservative); + // Handle bootstrap + if (Threads::number_of_threads() == 0) { + return; + } + // Do all RCU threads. CounterThreadCheck ctc(gbl_cnt); for (JavaThreadIteratorWithHandle jtiwh; JavaThread *thread = jtiwh.next(); ) { ctc.do_thread(thread); } we get: jib > # Internal Error (/scratch/mesos/slaves/c29d9578-9608-44e5-8e00-6c504a81f8a3-S889/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/5b3b9fa6-574d-4449-95da-14f1c0fbf0e4/runs/440a964e-2936-4785-9b28-d4fb67e38b18/workspace/open/src/hotspot/share/runtime/threadSMR.cpp:544), pid=89512, tid=9731 jib > # assert(cl.found() || _thread == VM_Exit::shutdown_thread()) failed: Acquired a ThreadsList snapshot from a thread not recognized by the Thread-SMR protocol. Current thread (0x00007faac0000800): JavaThread "Unknown thread" [_thread_in_vm, id=9731, stack(0x000000010ffd9000,0x00000001100d9000)] _threads_hazard_ptr=0x00007faabd605f60, _nested_threads_hazard_ptr_cnt=0 Stack: [0x000000010ffd9000,0x00000001100d9000], sp=0x00000001100d6890, free space=1014k Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code) V [libjvm.dylib+0xc5a475] VMError::report_and_die(int, char const*, char const*, __va_list_tag*, Thread*, unsigned char*, void*, void*, char const*, int, unsigned long)+0x609 V [libjvm.dylib+0xc5ab2d] VMError::report_and_die(Thread*, void*, char const*, int, char const*, char const*, __va_list_tag*)+0x47 V [libjvm.dylib+0x45b2df] report_vm_error(char const*, int, char const*, char const*, ...)+0xcc V [libjvm.dylib+0xbdd7f7] SafeThreadsListPtr::verify_hazard_ptr_scanned()+0xcd V [libjvm.dylib+0xbde08a] ThreadsListHandle::ThreadsListHandle(Thread*)+0x38 V [libjvm.dylib+0x5d8bed] GlobalCounter::write_synchronize()+0x137 V [libjvm.dylib+0xb85e67] void ConcurrentHashTable<Symbol*, SymbolTableConfig, (MemoryType)9>::delete_in_bucket<SymbolTableLookup>(Thread*, ConcurrentHashTable<Symbol*, SymbolTableConfig, (MemoryType)9>::Bucket*, SymbolTableLookup&)+0xf3 V [libjvm.dylib+0xb85a06] bool ConcurrentHashTable<Symbol*, SymbolTableConfig, (MemoryType)9>::internal_insert<SymbolTableLookup, SymbolTableCreateEntry, SymbolTableCreateEntry>(Thread*, SymbolTableLookup&, SymbolTableCreateEntry&, SymbolTableCreateEntry&, bool*, bool*)+0x20a V [libjvm.dylib+0xb82632] SymbolTable::do_add_if_needed(char const*, int, unsigned long, bool, Thread*)+0x7e V [libjvm.dylib+0xb82545] SymbolTable::lookup(char const*, int, Thread*)+0xf3 V [libjvm.dylib+0x9cd760] MethodMatcher::parse_method_pattern(char*&, char const*&, MethodMatcher*)+0x448 V [libjvm.dylib+0x9cdb13] BasicMatcher::parse_method_pattern(char*, char const*&)+0xa3 V [libjvm.dylib+0x3ee59d] CompilerOracle::parse_from_line(char*)+0x4b7 V [libjvm.dylib+0x3ef257] CompilerOracle::parse_from_string(char const*, void (*)(char*))+0x4b V [libjvm.dylib+0x3ef4a1] compilerOracle_init()+0x1a V [libjvm.dylib+0x62bae5] init_globals()+0xe5 V [libjvm.dylib+0xbd7fd6] Threads::create_vm(JavaVMInitArgs*, bool*)+0x26a V [libjvm.dylib+0x707dcf] JNI_CreateJavaVM+0xac C [java+0x3c79] JavaMain+0x10b C [libsystem_pthread.dylib+0x3661] _pthread_body+0x154 C [libsystem_pthread.dylib+0x350d] _pthread_body+0x0 C [libsystem_pthread.dylib+0x2bf9] thread_start+0xd --------------- P R O C E S S --------------- Threads class SMR info: _java_thread_list=0x00007faabd605f60, length=0, elements={ } _java_thread_list_alloc_cnt=1, _java_thread_list_free_cnt=0, _java_thread_list_max=0, _nested_thread_list_max=0 _delete_lock_wait_cnt=0, _delete_lock_wait_max=0 _to_delete_list_cnt=0, _to_delete_list_max=0 Java Threads: ( => current thread ) Other Threads: 0x00007faabf013800 GCTaskThread "GC Thread#0" [stack: 0x000070000fc36000,0x000070000fd36000] [id=20995] 0x00007faac0012000 ConcurrentGCThread "G1 Main Marker" [stack: 0x000070000fd39000,0x000070000fe39000] [id=20483] 0x00007faabe801800 ConcurrentGCThread "G1 Conc#0" [stack: 0x000070000fe3c000,0x000070000ff3c000] [id=12291] 0x00007faabf040800 ConcurrentGCThread "G1 Refine#0" [stack: 0x000070000ff3f000,0x000070001003f000] [id=12547] 0x00007faac001b000 ConcurrentGCThread "G1 Young RemSet Sampling" [stack: 0x0000700010042000,0x0000700010142000] [id=13059] =>0x00007faac0000800 (exited) JavaThread "Unknown thread" [_thread_in_vm, id=9731, stack(0x000000010ffd9000,0x00000001100d9000)] _threads_hazard_ptr=0x00007faabd605f60, _nested_threads_hazard_ptr_cnt=0 Threads with active compile tasks: VM state:not at safepoint (not fully initialized) VM Mutex/Monitor currently owned by a thread: None
03-08-2018

I will change the do_scan in "SymbolTable::symbols_do" to try_scan for now, but that needs to be investigated further. See JDK-8208462
27-07-2018

Here is the backtrace of the relevant threads showing the deadlock: (lldb) thread backtrace all thread #3 frame #0: 0x00007fff5376ca16 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007fff53935589 libsystem_pthread.dylib`_pthread_cond_wait + 732 frame #2: 0x0000000106782030 libjvm.dylib`os::PlatformEvent::park() + 254 frame #3: 0x0000000106922469 libjvm.dylib`ParkCommon(ParkEvent*, long) + 19 frame #4: 0x0000000106922c94 libjvm.dylib`Monitor::IWait(Thread*, long) + 202 frame #5: 0x0000000106924032 libjvm.dylib`Monitor::wait(bool, long, bool) + 1134 frame #6: 0x000000010692642e libjvm.dylib`VMThread::execute(VM_Operation*) + 932 frame #7: 0x0000000106f9d3ce libjvm.dylib`HeapDumper::dump(char const*) + 466 frame #8: 0x0000000106f9d753 libjvm.dylib`HeapDumper::dump_heap(bool) + 443 frame #9: 0x0000000106bbcd09 libjvm.dylib`report_java_out_of_memory(char const*) + 79 frame #10: 0x00000001067b8480 libjvm.dylib`Metaspace::report_metadata_oome(ClassLoaderData*, unsigned long, MetaspaceObj::Type, Metaspace::MetadataType, Thread*) + 570 frame #11: 0x00000001067b8176 libjvm.dylib`Metaspace::allocate(ClassLoaderData*, unsigned long, MetaspaceObj::Type, Thread*) + 566 frame #12: 0x0000000106db575e libjvm.dylib`ConstantPool::allocate(ClassLoaderData*, int, Thread*) + 72 frame #13: 0x0000000106b6418f libjvm.dylib`ClassFileParser::parse_stream(ClassFileStream const*, Thread*) + 1209 frame #14: 0x0000000106b63ca8 libjvm.dylib`ClassFileParser::ClassFileParser(ClassFileStream*, Symbol*, ClassLoaderData*, Handle, InstanceKlass const*, GrowableArray<Handle>*, ClassFileParser::Publicity, Thread*) + 1338 frame #15: 0x0000000106b8c01c libjvm.dylib`KlassFactory::create_from_stream(ClassFileStream*, Symbol*, ClassLoaderData*, Handle, InstanceKlass const*, GrowableArray<Handle>*, Thread*) + 452 frame #16: 0x0000000106b2a955 libjvm.dylib`SystemDictionary::resolve_from_stream(Symbol*, Handle, Handle, ClassFileStream*, Thread*) + 251 frame #17: 0x0000000106b05aaa libjvm.dylib`jvm_define_class_common(JNIEnv_*, char const*, _jobject*, signed char const*, int, _jobject*, char const*, Thread*) + 724 frame #18: 0x0000000106b05d0f libjvm.dylib`JVM_DefineClassWithSource + 458 frame #19: 0x00000001092035bb libjava.dylib`Java_java_lang_ClassLoader_defineClass1(env=0x00007fad77800b90, cls=<unavailable>, loader=0x00000001053fb7c8, name=<unavailable>, data=<unavailable>, offset=<unavailable>, length=<unavailable>, pd=<unavailable>, source=<unavailable>) at ClassLoader.c:136 [opt] frame #20: 0x000000011a7931c4 thread #9, name = 'Java: VM Thread' frame #0: 0x00007fff5376cd82 libsystem_kernel.dylib`__semwait_signal + 10 frame #1: 0x00007fff536e7724 libsystem_c.dylib`nanosleep + 199 frame #2: 0x00000001067865a6 libjvm.dylib`os::naked_short_sleep(long) + 164 frame #3: 0x0000000106bbbb6c libjvm.dylib`SpinYield::yield_or_sleep() + 62 frame #4: 0x0000000106b3d6d9 libjvm.dylib`ConcurrentHashTable<Symbol*, SymbolTableConfig, (MemoryType)9>::lock_resize_lock(Thread*) + 149 frame #5: 0x0000000106b39b17 libjvm.dylib`void ConcurrentHashTable<Symbol*, SymbolTableConfig, (MemoryType)9>::do_scan<SymbolsDo>(Thread*, SymbolsDo&) + 97 frame #6: 0x0000000106b39aac libjvm.dylib`SymbolTable::symbols_do(SymbolClosure*) + 148 frame #7: 0x0000000106f9cb2f libjvm.dylib`VM_HeapDumper::doit() + 367 frame #8: 0x00000001069a1dc5 libjvm.dylib`VM_Operation::evaluate() + 177 frame #9: 0x0000000106925dd5 libjvm.dylib`VMThread::evaluate_operation(VM_Operation*) + 283 frame #10: 0x0000000106925716 libjvm.dylib`VMThread::loop() + 372 frame #11: 0x000000010692546e libjvm.dylib`VMThread::run() + 206 frame #12: 0x000000010678411d libjvm.dylib`thread_native_entry(Thread*) + 309 frame #13: 0x00007fff53934661 libsystem_pthread.dylib`_pthread_body + 340 frame #14: 0x00007fff5393450d libsystem_pthread.dylib`_pthread_start + 377 frame #15: 0x00007fff53933bf9 libsystem_pthread.dylib`thread_start + 13 thread #16, name = 'Java: Service Thread' frame #0: 0x00007fff5376ca16 libsystem_kernel.dylib`__psynch_cvwait + 10 frame #1: 0x00007fff53935589 libsystem_pthread.dylib`_pthread_cond_wait + 732 frame #2: 0x0000000106782030 libjvm.dylib`os::PlatformEvent::park() + 254 frame #3: 0x0000000106922338 libjvm.dylib`Monitor::ILock(Thread*) + 310 frame #4: 0x00000001069234ed libjvm.dylib`Monitor::lock_without_safepoint_check(Thread*) + 177 frame #5: 0x00000001069c1a73 libjvm.dylib`SafepointSynchronize::block(JavaThread*) + 561 frame #6: 0x0000000106a56623 libjvm.dylib`SafepointMechanism::block_if_requested_local_poll(JavaThread*) + 35 frame #7: 0x0000000106a5659f libjvm.dylib`ThreadStateTransition::transition_and_fence(JavaThread*, JavaThreadState, JavaThreadState) + 191 frame #8: 0x0000000106b3b553 libjvm.dylib`SymbolTable::grow(JavaThread*) + 193 frame #9: 0x0000000106b3bce1 libjvm.dylib`SymbolTable::concurrent_work(JavaThread*) + 149 frame #10: 0x0000000106934588 libjvm.dylib`ServiceThread::service_thread_entry(JavaThread*, Thread*) + 438 frame #11: 0x000000010692b46d libjvm.dylib`JavaThread::thread_main_inner() + 367 frame #12: 0x000000010692afd6 libjvm.dylib`JavaThread::run() + 646 frame #13: 0x000000010678411d libjvm.dylib`thread_native_entry(Thread*) + 309 frame #14: 0x00007fff53934661 libsystem_pthread.dylib`_pthread_body + 340 frame #15: 0x00007fff5393450d libsystem_pthread.dylib`_pthread_start + 377 frame #16: 0x00007fff53933bf9 libsystem_pthread.dylib`thread_start + 13
27-07-2018

Changing the initial size of the table to 32768 works.
27-07-2018

Turning "-Xlog:symboltable=trace" shows: [0.021s][trace][symboltable] Start size: 16384 (14) [44.871s][trace][symboltable] Set uncleaned items:0 [44.871s][debug][symboltable] Concurrent work triggered, live factor:5.026855 dead factor:0.000000 [44.962s][trace][symboltable] Started to grow [44.977s][debug][symboltable] Grown to size:32768 so, we're resizing. I wonder if adding "-XSymbolTableSize=32768" is a reasonable workaround for the test. Either that, or bump up the initial table size up to 32,768, from 16,384
25-07-2018

There is an issue with open/test/hotspot/jtreg/runtime/ErrorHandling/TestHeapDumpOnOutOfMemoryErrorInMetaspace.java The test seems to create a lot of Symbols, and we end up timing out (the table resizes or rehashes?) My modified test based on the TestHeapDumpOnOutOfMemoryErrorInMetaspace.java one that I can easily debug, shows a regression from 0m1.013s to 1m16.290s, almost 100 times slower: date ; time java -XX:MaxMetaspaceSize=64m test ; date Wed Jul 25 11:46:07 CDT 2018 real 0m1.013s user 0m2.036s sys 0m0.101s Wed Jul 25 11:46:08 CDT 2018 date ; time jdk12/build/xcode/build/jdk/bin/java -XX:MaxMetaspaceSize=64m test ; date Wed Jul 25 11:47:21 CDT 2018 real 1m16.290s user 1m19.625s sys 0m0.292s Wed Jul 25 11:48:37 CDT 2018
25-07-2018

I'd like to wait a bit with this fix until we understand the performance characteristics of the new concurrent hash table, unless this is required by ZGC for 11.
14-05-2018