JDK-8023037 : Race between ciEnv::register_method and nmethod::make_not_entrant_or_zombie
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: hs25
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2013-08-14
  • Updated: 2017-11-15
  • Resolved: 2013-11-08
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 8 Other Other
8Fixed hs25Fixed hs25,port-stage-ppc-aixFixed
Related Reports
Relates :  
Relates :  
Relates :  
Description
Tests nsk/jvmti/RedefineClasses/StressRedefine and nsk/jvmti/RedefineClasses/StressRedefineWithoutBytecodeCorruption do the following: class methods being invoked aggressively while class itself being redefined with jvmti with multiple threads. These tests hang sometimes. pstack shows that hotspot is working and doing some compiler work that never ends. 

Steps to reproduce: go to sc11136470.us.oracle.com, cd to /export/local/repr1 and run "repr.sh" script in background. Wait until test run takes more than couple of minutes.  It took 9 attempts to hang last time.

I've launched script (it's dump_loop.sh in the same dir) that launches pstack every 5 seconds. Results can be found in "10029" dir. Several core files can be found there as well. Also I'll attach several pstack snapshots here.

RULE nsk/jvmti/RedefineClasses/StressRedefineWithoutBytecodeCorruption Timeout none
RULE nsk/jvmti/RedefineClasses/StressRedefine Timeout none

Build that I used:
java version "1.8.0-ea-fastdebug"
Java(TM) SE Runtime Environment (build 1.8.0-ea-fastdebug-b102)
Java HotSpot(TM) Server VM (build 25.0-b44-fastdebug, mixed mode)
Comments
The bug is present only in non-product builds since nmethod verification is absent in product bits.
06-11-2013

Ignore my previous comment about sweeper. The problem is triggered by class redefinition and it can be performed under Compile_lock or during a safepoint. So, in ciEnv::register_method it's not enough to grab Compile_lock, but we need to ensure that there are no safepoints possible during method installation. There's one place in nmethod verification code (see MutexLocker ml_verify (CompiledIC_lock) in nmethod::verify_interrupt_point) where safepoint is possible and it causes the failure.
06-11-2013

There's a race between compiler thread during method registration and sweeper: sweeper can invalidate a nmethod which hasn't been installed yet. Consider the following scenario: - ciEnv::register_method: new nmethod(...) - sweeper: invalidates that nmethod and patches VEP to call handle_wrong_method - sweeper: tries to unlink, but method()->from_compiled_entry() != verified_entry_point()) - ciEnv::register_method: installs invalidated nmethod So, an attempt to call corresponding Java method will lead to infinite loop: VEP of the compiled method calls handle_wrong_method and call site resolution points to the very same compiled method.
03-11-2013

nmethod unlinking is done later in nmethod::make_not_entrant_or_zombie: if (method() != NULL && (method()->code() == this || method()->from_compiled_entry() == verified_entry_point())) { HandleMark hm; method()->clear_code(); } But for some reason it didn't fire for the method.
01-11-2013

Verified entry point of resolved method is patched to jump back to handle_wrong_method runtime stub: java/lang/reflect/Constructor::newInstance - compiled code: 0x7fee0d810b10 Compiled method (c2) 4204600 2464 4 java.lang.reflect.Constructor::newInstance (87 bytes) [Verified Entry Point] ;; B1: # B34 B2 <- BLOCK HEAD IS JUNK Freq: 1 0x00007fee0d810cf0: jmpq 0x00007fee0d315060 <==== handle_wrong_method stub 0x00007fee0d810cf5: (bad) ... That's the reason why all the threads are in infinite loop. nmethod::make_not_entrant_or_zombie does exactly the same thing: if (!is_osr_method() && !is_not_entrant()) { NativeJump::patch_verified_entry(entry_point(), verified_entry_point(), SharedRuntime::get_handle_wrong_method_stub()); } And both compiled versions were invalidated indeed: 49833 2464 4 java.lang.reflect.Constructor::newInstance (87 bytes) made not entrant ... 49838 702 2 java.lang.reflect.Constructor::newInstance (87 bytes) made not entrant The question is why it is still referenced from the Method then?
01-11-2013

The threads continuously reresolve the call site to exactly the same method: handle_wrong_method reresolving call to java.lang.reflect.Constructor::newInstance code: 0x00007feb361eedd0 callinfo.selected_method(): {method} - this oop: 0x00007feab29fb480 - method holder: 'java/lang/reflect/Constructor' - constants: 0x00007feab29f97e8 constant pool [318] {0x00007feab29f97e8} for 'java/lang/reflect/Constructor' cache=0x00007feab2af1190 - access: 0x80000081 public transient - name: 'newInstance' - signature: '([Ljava/lang/Object;)Ljava/lang/Object;' - max stack: 6 - max locals: 4 - size of params: 2 - method size: 12 - highest level: 4 - vtable index: -2 - i2i entry: 0x00007feb35f49e00 - adapters: AHE@0x00000000016a39c0: 0xbb000000 i2c: 0x00007feb35ff7320 c2i: 0x00007feb35ff7435 c2iUV: 0x00007feb35ff740b - compiled entry 0x00007feb361eefb0 - code size: 87 - code start: 0x00007feab29fb3c8 - code end (excl): 0x00007feab29fb41f - method data: 0x00007feab0a26d40 - checked ex length: 4 - checked ex start: 0x00007feab29fb46c - linenumber start: 0x00007feab29fb41f - localvar length: 5 - localvar start: 0x00007feab29fb42e - compiled code: nmethod48702018 2650 4 java.lang.reflect.Constructor::newInstance (87 bytes) callinfo.selected_klass(): java.lang.reflect.Constructor {0x00007feab29fbf18} - instance size: 17 - klass size: 136 - access: public final synchronized - state: fully_initialized - name: 'java/lang/reflect/Constructor' - super: 'java/lang/reflect/Executable' - sub: - arrays: 'java/lang/reflect/Constructor'[] - methods: Array<T>(0x00007feab29fa2c0) - method ordering: Array<T>(0x00007feab29fc358) - default_methods: Array<T>(0x0000000000000000) - local interfaces: Array<T>(0x00007feab29a1010) - trans. interfaces: Array<T>(0x00007feab29f8cb0) - constants: constant pool [318] {0x00007feab29f97e8} for 'java/lang/reflect/Constructor' cache=0x00007feab2af1190 - class loader data: NULL class_loader - host class: NULL - source file: 'Constructor.java' - class annotations: Array<T>(0x0000000000000000) - class type annotations: Array<T>(0x0000000000000000) - field annotations: Array<T>(0x0000000000000000) - field type annotations: Array<T>(0x0000000000000000) - generic signature: '<T:Ljava/lang/Object;>Ljava/lang/reflect/Executable;' - inner classes: Array<T>(0x00007feab29a0fe0) - java mirror: a 'java/lang/Class' = 'java/lang/reflect/Constructor' - vtable length 56 (start addr: 0x00007feab29fc0e0) - itable length 20 (start addr: 0x00007feab29fc2a0) - ---- static fields (0 words): - ---- non-static fields (15 words): - 'override' 'Z' @16 - volatile 'securityCheckCache' 'Ljava/lang/Object;' @24 - private volatile transient 'hasRealParameterData' 'Z' @32 - private volatile transient 'parameters' '[Ljava/lang/reflect/Parameter;' @40 - private transient strict 'declaredAnnotations' 'Ljava/util/Map;' @48 - private 'slot' 'I' @56 - private 'modifiers' 'I' @60 - private strict 'clazz' 'Ljava/lang/Class;' @64 - private strict 'parameterTypes' '[Ljava/lang/Class;' @72 - private strict 'exceptionTypes' '[Ljava/lang/Class;' @80 - private transient 'signature' 'Ljava/lang/String;' @88 - private transient 'genericInfo' 'Lsun/reflect/generics/repository/ConstructorRepository;' @96 - private 'annotations' '[B' @104 - private 'parameterAnnotations' '[B' @112 - private volatile 'constructorAccessor' 'Lsun/reflect/ConstructorAccessor;' @120 - private strict 'root' 'Ljava/lang/reflect/Constructor;' @128 - non-static oop maps: 24-24 40-48 64-128 (gdb) print callinfo._selected_method._value._constMethod._method_idnum $25 = 7
31-10-2013

The method was compiled by C1 (@ tier 2): nmethod55765338 684 ! 2 java.lang.Class::newInstance (155 bytes) Call site being patched @ Class.java:433: public T newInstance() ... // Run constructor try { return tmpConstructor.newInstance((Object[])null); <======= } catch (InvocationTargetException e) { Unsafe.getUnsafe().throwException(e.getTargetException()); // Not reached return null; }
30-10-2013

The test hangs. Worker threads are contending on CompiledIC_lock in SharedRuntime::reresolve_call_site.
30-10-2013

VM events before the hang: Compilation events (10 events): Event: 33.938 Thread 0x0000000000d5a000 1165 4 com.sun.tools.javac.file.ZipFileIndex$Entry::getName (19 bytes) Event: 33.939 Thread 0x0000000000d5a000 nmethod 1165 0x00007fc9ed73bdd0 code [0x00007fc9ed73bf20, 0x00007fc9ed73c008] Event: 33.939 Thread 0x0000000000d5a000 604 4 java.util.ArrayList::elementData (7 bytes) Event: 33.941 Thread 0x0000000000d5a000 nmethod 604 0x00007fc9ed747750 code [0x00007fc9ed7478a0, 0x00007fc9ed747958] Event: 33.941 Thread 0x0000000000d5a000 1131 4 java.util.jar.Attributes$Name::isValid (45 bytes) Event: 33.948 Thread 0x0000000000d5a000 nmethod 1131 0x00007fc9ed748990 code [0x00007fc9ed748ae0, 0x00007fc9ed748d98] Event: 33.948 Thread 0x0000000000d5a000 1130 4 sun.misc.ASCIICaseInsensitiveComparator::lowerCaseHashCode (36 bytes) Event: 33.956 Thread 0x0000000000d5a000 nmethod 1130 0x00007fc9ed7481d0 code [0x00007fc9ed748320, 0x00007fc9ed7485f8] Event: 33.956 Thread 0x0000000000d5a000 1132 4 java.lang.String::<init> (100 bytes) Event: 33.971 Thread 0x0000000000d5a000 nmethod 1132 0x00007fc9ed752f10 code [0x00007fc9ed753060, 0x00007fc9ed753498] Deoptimization events (10 events): Event: 1.771 Thread 0x00007fc96462c000 Uncommon trap: reason=unreached action=reinterpret pc=0x00007fc9ed40f6b0 method=java.lang.ThreadLocal.get()Ljava/lang/Object; @ 11 Event: 1.865 Thread 0x00007fc9646c5000 Uncommon trap: reason=unreached action=reinterpret pc=0x00007fc9ed417918 method=java.lang.ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry; @ 21 Event: 1.866 Thread 0x00007fc9646c5000 Uncommon trap: reason=class_check action=maybe_recompile pc=0x00007fc9ed39d0b0 method=sun.misc.URLClassPath.getLoader(I)Lsun/misc/URLClassPath$Loader; @ 94 Event: 1.867 Thread 0x00007fc9646c5000 Uncommon trap: reason=class_check action=maybe_recompile pc=0x00007fc9ed39d0b0 method=sun.misc.URLClassPath.getLoader(I)Lsun/misc/URLClassPath$Loader; @ 94 Event: 1.871 Thread 0x00007fc9646c9800 Uncommon trap: reason=unreached action=reinterpret pc=0x00007fc9ed424d10 method=java.lang.ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry; @ 21 Event: 1.884 Thread 0x00007fc9646c7000 Uncommon trap: reason=unreached action=reinterpret pc=0x00007fc9ed3d9144 method=java.lang.ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry; @ 21 Event: 1.887 Thread 0x00007fc9646e5000 Uncommon trap: reason=unreached action=reinterpret pc=0x00007fc9ed40d6a4 method=java.lang.ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry; @ 21 Event: 17.677 Thread 0x00007fc95c529000 Uncommon trap: reason=null_check action=make_not_entrant pc=0x00007fc9ed5b9774 method=com.sun.tools.javac.util.Options.get(Lcom/sun/tools/javac/main/Option;)Ljava/lang/String; @ 11 Event: 17.738 Thread 0x00007fc95c854000 Uncommon trap: reason=range_check action=make_not_entrant pc=0x00007fc9ed59c688 method=java.lang.Character.codePointAtImpl([CII)I @ 2 Event: 17.763 Thread 0x00007fc9646c5000 Uncommon trap: reason=null_check action=make_not_entrant pc=0x00007fc9ed5b9774 method=com.sun.tools.javac.util.Options.get(Lcom/sun/tools/javac/main/Option;)Ljava/lang/String; @ 11 Events (10 events): Event: 31.621 Thread 0x0000000001643000 DEOPT PACKING pc=0x00007fc9ed6bd660 sp=0x00007fc961a4cba0 Event: 31.621 Thread 0x0000000001643000 DEOPT UNPACKING pc=0x00007fc9ed22cfd1 sp=0x00007fc961a4c938 mode 1 Event: 31.621 Thread 0x0000000001643000 DEOPT PACKING pc=0x00007fc9ed6bd660 sp=0x00007fc961a4cba0 Event: 31.621 Thread 0x0000000001643000 DEOPT UNPACKING pc=0x00007fc9ed22cfd1 sp=0x00007fc961a4c938 mode 1 Event: 31.626 Executing VM operation: RedefineClasses Event: 31.645 Executing VM operation: RedefineClasses done Event: 31.706 Executing VM operation: RedefineClasses Event: 31.726 Executing VM operation: RedefineClasses done Event: 31.899 Thread 0x0000000000d5f800 flushing nmethod 0x00007fc9ed587790 Event: 32.772 Thread 0x0000000000d5f800 flushing nmethod 0x00007fc9ed5e5090
30-10-2013

[Describe stack] 1. C frame (sp=0x00007fc960538e80 unextended sp=0x00007fc960538e80, fp=0x0000000000000000, real_fp=0x00007fc960539120, pc=0x00007fc9ed15b0da) RuntimeStub (0x00007fc9ed15b010): wrong_method_stub 2. Compiled frame (sp=0x00007fc960539120 unextended sp=0x00007fc960539120, fp=0x00007fc960539288, real_fp=0x00007fc960539230, pc=0x00007fc9ed5135dc) nmethod55765338 684 ! 2 java.lang.Class::newInstance (155 bytes) 3. Interpreted frame (sp=0x00007fc960539230 unextended sp=0x00007fc960539230, fp=0x00007fc960539288, real_fp=0x00007fc960539288, pc=0x00007fc9ed15c717) (~return entry points [0x00007fc9ed15b9c0, 0x00007fc9ed15dca0] 8928 bytes ) BufferBlob (0x00007fc9ed15b390) used for Interpreter 4. Interpreted frame (sp=0x00007fc960539298 unextended sp=0x00007fc9605392a8, fp=0x00007fc960539300, real_fp=0x00007fc960539300, pc=0x00007fc9ed15c717) (~return entry points [0x00007fc9ed15b9c0, 0x00007fc9ed15dca0] 8928 bytes ) BufferBlob (0x00007fc9ed15b390) used for Interpreter ...
30-10-2013

"Executing ps" for thread: "Thread-58" #67 prio=5 os_prio=0 tid=0x00007fc95c934800 nid=0x5216 runnable [0x00007fc95bffd000] java.lang.Thread.State: RUNNABLE JavaThread state: _thread_blocked Thread: 0x00007fc95c934800 [0x5216] State: _running _has_called_back 0 _at_poll_safepoint 0 JavaThread state: _thread_blocked 1 - frame( sp=0x00007fc95bffdea0, unextended_sp=0x00007fc95bffdea0, fp=0x00007fc95bffe008, pc=0x00007fc9ed5135dc) java.lang.Class.newInstance(Class.java:433) 2 - frame( sp=0x00007fc95bffdfb0, unextended_sp=0x00007fc95bffdfb0, fp=0x00007fc95bffe008, pc=0x00007fc9ed15c717) javax.tools.ToolProvider.getSystemTool(ToolProvider.java:160) 3 - frame( sp=0x00007fc95bffe018, unextended_sp=0x00007fc95bffe028, fp=0x00007fc95bffe080, pc=0x00007fc9ed15c717) javax.tools.ToolProvider.getSystemJavaCompiler(ToolProvider.java:102) 4 - frame( sp=0x00007fc95bffe090, unextended_sp=0x00007fc95bffe090, fp=0x00007fc95bffe0d0, pc=0x00007fc9ed15c717) metaspace.compiler.InMemoryCompiler.compile(InMemoryCompiler.java:16) 5 - frame( sp=0x00007fc95bffe0e0, unextended_sp=0x00007fc95bffe100, fp=0x00007fc95bffe148, pc=0x00007fc9ed15c717) nsk.jvmti.RedefineClasses.StressRedefine.generateAndCompile(StressRedefine.java:185) 6 - frame( sp=0x00007fc95bffe158, unextended_sp=0x00007fc95bffe160, fp=0x00007fc95bffe1a0, pc=0x00007fc9ed15c717) nsk.jvmti.RedefineClasses.StressRedefine.access$200(StressRedefine.java:36) 7 - frame( sp=0x00007fc95bffe1b0, unextended_sp=0x00007fc95bffe1b0, fp=0x00007fc95bffe1f0, pc=0x00007fc9ed15c717) nsk.jvmti.RedefineClasses.StressRedefine$Worker.run(StressRedefine.java:147) 8 - frame( sp=0x00007fc95bffe200, unextended_sp=0x00007fc95bffe220, fp=0x00007fc95bffe268, pc=0x00007fc9ed15cd02) java.lang.Thread.run(Thread.java:744)
30-10-2013

Moving it back to compiler but you might be able to close it (see above).
01-10-2013

These frames are called by the c2 compiler: #8 0xf6f7fc55 in SharedRuntime::reresolve_call_site (thread=0xe2567800, __the_thread__=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/sharedRuntime.cpp:1613 #9 0xf6f7ffac in SharedRuntime::handle_wrong_method (thread=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/sharedRuntime.cpp:1339 #10 0xf425ef6c in ?? () But I don't think this is going to be reproduce-able because I ran this thousands of times on this machine with the fix that I had. Vladimir, have you been able to reproduce this after JDK-8022887?
01-10-2013

Stack trace analysis from Vladimir shows that this is a runtime issue
01-10-2013

I'm starting to think this machine needs memtester run on it. Except the failure I get is consistent. Aleksey, did you write this test? Where are the sources? Do you have a class with 400 static methods that you redefine to delete all but 6 after you create a java_lang_reflect_Method out of the 376th one? Or is there a memory corruption with this j.l.r.M instance?
21-08-2013

Same test but different failure mode. Related?
16-08-2013

Looks like VM is stuck in SharedRuntime::handle_wrong_method / SharedRuntime::reresolve_call_site. Stack trace sampling showed that 1 thread always has SharedRuntime::reresolve_call_site on the stack : ... #8 0xf6f7fc55 in SharedRuntime::reresolve_call_site (thread=0xe2567800, __the_thread__=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/sharedRuntime.cpp:1613 #9 0xf6f7ffac in SharedRuntime::handle_wrong_method (thread=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/sharedRuntime.cpp:1339 #10 0xf425ef6c in ?? () #11 0xf43f0ac8 in ?? () #12 0xf6c55c87 in JavaCalls::call_helper (result=0xe21c826c, m=0xe21c817c, args=0xe21c81cc, __the_thread__=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/javaCalls.cpp:402 #13 0xf6edd849 in os::os_exception_wrapper (f=0xf6c544a0 <JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*)>, value=0xe21c826c, method=0xe21c817c, args=0xe21c81cc, thread=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/os/linux/vm/os_linux.cpp:4796 #14 0xf6c5635b in JavaCalls::call_virtual (result=0xe21c826c, spec_klass=..., name=0xe31a7130, signature=0xe31a8510, args=0xe21c81cc, __the_thread__=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/javaCalls.cpp:307 #15 0xf6c56a11 in JavaCalls::call_virtual (result=0xe21c826c, receiver=..., spec_klass=..., name=0xe31a7130, signature=0xe31a8510, __the_thread__=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/javaCalls.cpp:210 #16 0xf6d16b1e in thread_entry (thread=0xe2567800, __the_thread__=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/prims/jvm.cpp:2822 #17 0xf7016429 in JavaThread::thread_main_inner (this=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/thread.cpp:1698 #18 0xf7016738 in JavaThread::run (this=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/share/vm/runtime/thread.cpp:1678 #19 0xf6ee5e69 in java_start (thread=0xe2567800) at /HUDSON/workspace/2-build-linux-i586/jdk8/5336/hotspot/src/os/linux/vm/os_linux.cpp:859 #20 0x431afa09 in start_thread () from /lib/libpthread.so.0 #21 0x430c100e in clone () from /lib/libc.so.6
15-08-2013