JDK-8023004 : JSR 292: java.lang.RuntimeException: Original target method was called.
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: hs25,7u60
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2013-08-14
  • Updated: 2014-10-15
  • Resolved: 2013-10-24
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 7 JDK 8 Other
7u60Fixed 8Fixed hs25Fixed
Related Reports
Relates :  
JDK-8040201 - JSR 292: old non-redefined code is entered again after JVMTI PopFrame followed by class redefinition in MethodHandle.invoke
Relates :  
JDK-8027162 - JSR292: implement MemberName interning
Relates :  
JDK-8009616 - java/lang/invoke/MethodHandlesTest.java failure: testAsInterfaceInstance
Description
[2013-08-13T06:30:48.24] Original bootstrap(): Lookup vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0; method name = greet; method type = (Object,String,int)Boolean
[2013-08-13T06:30:48.28] # ERROR: Test caught an exception: 
[2013-08-13T06:30:48.28] # ERROR: java.lang.reflect.InvocationTargetException
[2013-08-13T06:30:48.28] # ERROR: 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2013-08-13T06:30:48.29] # ERROR: 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[2013-08-13T06:30:48.29] # ERROR: 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2013-08-13T06:30:48.29] # ERROR: 	at java.lang.reflect.Method.invoke(Method.java:491)
[2013-08-13T06:30:48.30] # ERROR: 	at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.run(IndyRedefineTest.java:25)
[2013-08-13T06:30:48.30] # ERROR: 	at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:225)
[2013-08-13T06:30:48.30] # ERROR: 	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:141)
[2013-08-13T06:30:48.31] # ERROR: 	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:111)
[2013-08-13T06:30:48.31] # ERROR: 	at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.main(IndyRedefineTest.java:39)
[2013-08-13T06:30:48.31] # ERROR: Caused by: java.lang.RuntimeException: Original target method was called. Test failed.
[2013-08-13T06:30:48.32] # ERROR: 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget0(Unknown Source)
[2013-08-13T06:30:48.32] # ERROR: 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget0(Unknown Source)
[2013-08-13T06:30:48.32] # ERROR: 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget(Unknown Source)
[2013-08-13T06:30:48.33] # ERROR: 	... 9 more
[2013-08-13T06:30:48.39] # ERROR: Test caught an exception: 
[2013-08-13T06:30:48.40] # ERROR: java.lang.RuntimeException
[2013-08-13T06:30:48.40] # ERROR: 	at vm.mlvm.share.MlvmTest.throwAsUnckechedException(MlvmTest.java:184)
[2013-08-13T06:30:48.40] # ERROR: 	at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:236)
[2013-08-13T06:30:48.41] # ERROR: 	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:141)
[2013-08-13T06:30:48.41] # ERROR: 	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:111)
[2013-08-13T06:30:48.41] # ERROR: 	at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.main(IndyRedefineTest.java:39)
[2013-08-13T06:30:48.42] # ERROR: Caused by: java.lang.reflect.InvocationTargetException
[2013-08-13T06:30:48.42] # ERROR: 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2013-08-13T06:30:48.42] # ERROR: 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[2013-08-13T06:30:48.43] # ERROR: 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2013-08-13T06:30:48.43] # ERROR: 	at java.lang.reflect.Method.invoke(Method.java:491)
[2013-08-13T06:30:48.44] # ERROR: 	at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.run(IndyRedefineTest.java:25)
[2013-08-13T06:30:48.44] # ERROR: 	at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:225)
[2013-08-13T06:30:48.44] # ERROR: 	... 3 more
[2013-08-13T06:30:48.45] # ERROR: Caused by: java.lang.RuntimeException: Original target method was called. Test failed.
[2013-08-13T06:30:48.46] # ERROR: 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget0(Unknown Source)
[2013-08-13T06:30:48.46] # ERROR: 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget0(Unknown Source)
[2013-08-13T06:30:48.47] # ERROR: 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget(Unknown Source)
[2013-08-13T06:30:48.47] # ERROR: 	... 9 more
[2013-08-13T06:30:48.64] ### TRACE 1: TEST FAILED
[2013-08-13T06:30:48.71] Exception in thread "main" java.lang.RuntimeException
[2013-08-13T06:30:48.71] 	at vm.mlvm.share.MlvmTest.throwAsUnckechedException(MlvmTest.java:184)
[2013-08-13T06:30:48.72] 	at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:236)
[2013-08-13T06:30:48.73] 	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:141)
[2013-08-13T06:30:48.75] 	at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:111)
[2013-08-13T06:30:48.76] 	at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.main(IndyRedefineTest.java:39)
[2013-08-13T06:30:48.76] Caused by: java.lang.reflect.InvocationTargetException
[2013-08-13T06:30:48.81] 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2013-08-13T06:30:48.82] 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
[2013-08-13T06:30:48.82] 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2013-08-13T06:30:48.83] 	at java.lang.reflect.Method.invoke(Method.java:491)
[2013-08-13T06:30:48.83] 	at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.run(IndyRedefineTest.java:25)
[2013-08-13T06:30:48.83] 	at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:225)
[2013-08-13T06:30:48.84] 	... 3 more
[2013-08-13T06:30:48.84] Caused by: java.lang.RuntimeException: Original target method was called. Test failed.
[2013-08-13T06:30:48.85] 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget0(Unknown Source)
[2013-08-13T06:30:48.85] 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget0(Unknown Source)
[2013-08-13T06:30:48.86] 	at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget(Unknown Source)
[2013-08-13T06:30:48.86] 	... 9 more
Comments
7u60-critical-request justification: This bug fix is better to be in the release because it is a part of the JSR-292 support in the JVMTI HotSwap API (includes RedefineClasses, RetransformClasses and PopFrame). This bug is one of 12 bug fixes that depend on each other and must be integrated in the order: https://jbs.oracle.com/bugs/browse/JDK-7194607 https://jbs.oracle.com/bugs/browse/JDK-8005128 https://jbs.oracle.com/bugs/browse/JDK-8006542 https://jbs.oracle.com/bugs/browse/JDK-8006546 https://jbs.oracle.com/bugs/browse/JDK-8006731 https://jbs.oracle.com/bugs/browse/JDK-8008511 https://jbs.oracle.com/bugs/browse/JDK-8007037 https://jbs.oracle.com/bugs/browse/JDK-8014288 https://jbs.oracle.com/bugs/browse/JDK-8013945 https://jbs.oracle.com/bugs/browse/JDK-8014052 https://jbs.oracle.com/bugs/browse/JDK-7187554 https://jbs.oracle.com/bugs/browse/JDK-8023004 All the fixes above have been already integrated into the JDK 8 and tested in the hotspot-rt nightly for several months. Risk: low The fixes touch the JVMTI HotSwap API that includes RedefineClasses, RetransformClasses and PopFrame. The risk is only to introduce regressions in this part of the JVMTI implementation. This impacts only the debugging and profiling tools that use the JVMTI HotSwap feature. There are very small chances for regressions to sneak into the class file constant pool processing and method handles implementation. Webrevs and reviewers: The 7u60 webrevs location is: http://javaweb.sfbay.sun.com/java/svc/ss45998/webrevs/2013/hotspot/7u_port/ The fixes above were already passed the review process before integration into JDK 8. The reviewers were: twisti, jrose, coleenp, dholmes, etc. The 7u60 edition of fixes must be reviewed at least by jrose and twisti. Level of effort: All fixes need a secondary review phase after rebase from jdk8 to 7u60 repository. Testing coverage: The folllowing test suites must be run to ensure correctness of the fixes: JTREG tests: com/sun/jdi, java/lang/instrument NSK tests: vm.mlvm.testlist, nsk.jvmti.testlist, nsk.jdi.testlist, nsk.jdwp.testlist Result of not integrating: The users will not be able to use HotSwap technology for debuging and profiling Java code that depends on the JSR-292 implementation. In that case the integration of these fixes will have to be requested/escalated in 7 updates by the tool vendors and/or customers.
10-01-2014
I agree with the change proposed by Serguei. It is a conservative change to getMemberVMInfo, and also an improvement. It is amazing that such an unimportant function can have such a non-local effect. It points up a possible weakness in add_member_name. Is there some way for add_member_name to detect when it gets a redundant add request and report an error? I'm looking forward to reworking the member name table in Java.
23-10-2013
Ok, got the root cause of this. The problem is here: oop MethodHandles::init_method_MemberName(Handle mname, CallInfo& info) { . . . . . . . . m->method_holder()->add_member_name(m->method_idnum(), mname); return mname(); } The call to add_member_name() resets the member name at the index m->method_idnum(). After that one of the two member names with the same method_idnum() is out of the MNT and is not updated when the method is redefined. If I understand this correctly, we should no have two different member names for the same method. The following patch fixes the issue (not sure if it is exactly right, but looks as low risk): diff -r ac9cb1d5a202 src/share/vm/prims/methodHandles.cpp --- a/src/share/vm/prims/methodHandles.cpp Mon Oct 07 12:20:28 2013 -0400 +++ b/src/share/vm/prims/methodHandles.cpp Fri Oct 11 15:05:24 2013 -0700 @@ -1194,9 +1194,7 @@ JVM_ENTRY(jobject, MHN_getMemberVMInfo(J } else if (vmtarget->is_klass()) { x = ((Klass*) vmtarget)->java_mirror(); } else if (vmtarget->is_method()) { - Handle mname2 = MethodHandles::new_MemberName(CHECK_NULL); - CallInfo info((Method*)vmtarget); - x = MethodHandles::init_method_MemberName(mname2, info); + x = mname(); } result->obj_at_put(1, x); return JNIHandles::make_local(env, result());
11-10-2013
Thanks, Vladimir. Ok, I see that the assert is just to trigger the call to MemberName.vminfoIsConsistent() in the MemberName.Factory.resolve(): assert(m.vminfoIsConsistent()); ... and the vminfoIsConsistent() is to trigger the call to MethodHandleNatives.getMemberVMInfo().
11-10-2013
Serguei, thanks for additional info. I experimented with different versions of the code and the failure occurs only when MethodHandleNatives.getMemberVMInfo() is called. It doesn't matter whether assertions are turned on or off while getMemberVMInfo is called.
11-10-2013
Vladimir, Why do you think the culprit is the MethodHandleNatives.getMemberVMInfo()? Just need to understand the reason. What do you observe? Do you see the assert() fired after the call to getMemberVMInfo()?
11-10-2013
In failing case the redefineNow() is called because the original target() method is executed: public static Boolean target(Object o, String s, int i) { redefineNow(); throw new RuntimeException("Original target method was called. Test failed."); } In passing case the redefined target() method is executed that does not have a call to the redefineNow(): public static Boolean target(Object o, String s, int i) { MlvmTest.getLog().display("Redefined target called! Object = " + o + "; string = " + s + "; int = " + i); MlvmTest.getLog().display("The rest of methods are from " + (isRedefinedClass() ? "redefined" : "original") + " class"); return true; }
11-10-2013
But I suspect it can be a timing issue and MethodHandleNatives.getMemberVMInfo isn't the root cause. When the test fails it tries to redefine a class twice: - IndyRedefineClass.c, 109: Entering redefine tigger method: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0;.redefineNow - IndyRedefineClass.c, 117: Redefining class vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0 ... - IndyRedefineClass.c, 109: Entering redefine tigger method: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0;.redefineNow - IndyRedefineClass.c, 113: Class is already redefined. It's not the case when the test passes.
11-10-2013
Serguei, David, thank you for the analysis. The culprit is MethodHandleNatives.getMemberVMInfo (called from MemberName.vminfoIsConsistent).
11-10-2013
See the difference in tracing below. The good case: . . . - IndyRedefineClass.c, 109: Entering redefine tigger method: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0;.redefineNow - IndyRedefineClass.c, 117: Redefining class vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0 # info :: File = /net/sqenfs-1.us.oracle.com/export1/comp/vm/testbase/sqe/vm/8/build/execution/vm/bin/newclass/vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0.class # info **Agent:: opening file /net/sqenfs-1.us.oracle.com/export1/comp/vm/testbase/sqe/vm/8/build/execution/vm/bin/newclass/vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0.class # info file size= 3394 File red completely - IndyRedefineClass.c, 71: Enabling single step - IndyRedefineClass.c, 80: Forcing early return - IndyRedefineClass.c, 145: Single step event: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0; .target :3 - IndyRedefineClass.c, 71: Enabling single step - IndyRedefineClass.c, 76: Popping a frame - IndyRedefineClass.c, 145: Single step event: Ljava/lang/invoke/LambdaForm$DMH; .invokeStatic_LLI_L :e - IndyRedefineClass.c, 65: Disabling single step - IndyRedefineClass.c, 48: The following values should be non-zero for test to pass: - IndyRedefineClass.c, 49: Method entry event fired? 1 - IndyRedefineClass.c, 50: Single step event fired? 1 - IndyRedefineClass.c, 51: The following value should be zero for test to pass: - IndyRedefineClass.c, 52: Any other error occured? 0 ### TRACE 1: TEST PASSED The bad case: . . . - IndyRedefineClass.c, 109: Entering redefine tigger method: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0;.redefineNow - IndyRedefineClass.c, 117: Redefining class vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0 # info :: File = /net/sqenfs-1.us.oracle.com/export1/comp/vm/testbase/sqe/vm/8/build/execution/vm/bin/newclass/vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0.class # info **Agent:: opening file /net/sqenfs-1.us.oracle.com/export1/comp/vm/testbase/sqe/vm/8/build/execution/vm/bin/newclass/vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0.class # info file size= 3394 File red completely - IndyRedefineClass.c, 71: Enabling single step - IndyRedefineClass.c, 80: Forcing early return - IndyRedefineClass.c, 145: Single step event: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0; .target :3 - IndyRedefineClass.c, 71: Enabling single step - IndyRedefineClass.c, 76: Popping a frame - IndyRedefineClass.c, 145: Single step event: Ljava/lang/invoke/LambdaForm$DMH; .invokeStatic_LLI_L :e - IndyRedefineClass.c, 65: Disabling single step - IndyRedefineClass.c, 109: Entering redefine tigger method: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0;.redefineNow - IndyRedefineClass.c, 113: Class is already redefined. Exception <a 'java/lang/RuntimeException'> (0xfffffffe0063c538) thrown in interpreter method <{method} {0xffffffff69020b78} 'target' '(Ljava/lang/Object;Ljava/lang/String;I)Ljava/lang/Boolean;'> at bci 12 for thread 0x0000000100112800 Exception <a 'java/lang/RuntimeException'> (0xfffffffe0063c538) thrown in interpreter method <{method} {0xffffffff6902d638} 'invokeStatic_LLI_L' '(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang> at bci 14 for thread 0x0000000100112800 Exception <a 'java/lang/RuntimeException'> (0xfffffffe0063c538) thrown in interpreter method <{method} {0xffffffff6902da28} 'linkToCallSite' '(Ljava/lang/Object;Ljava/lang/Object;ILjava/lang/Ob> at bci 14 for thread 0x0000000100112800 Exception <a 'java/lang/RuntimeException'> (0xfffffffe0063c538) thrown in interpreter method <{method} {0xffffffff69020d98} 'invokeTarget0' '()Z' in 'vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b> at bci 18 for thread 0x0000000100112800 Exception <a 'java/lang/RuntimeException'> (0xfffffffe0063c538) thrown in interpreter method <{method} {0xffffffff69020cb8} 'invokeTarget' '()Z' in 'vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/> at bci 0 for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown [/net/sc11152541/export/home/sspitsyn/hsx4/hotspot/src/share/vm/runtime/reflection.cpp, line 1080] for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown in interpreter method <{method} {0xffffffff68f33548} 'invoke0' '(Ljava/lang/reflect/Method;Ljava/lang/Object;[Ljava/lang/O> at bci 0 for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown in interpreter method <{method} {0xffffffff68f333f8} 'invoke' '(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;' > at bci 87 for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown in interpreter method <{method} {0xffffffff68f33b58} 'invoke' '(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;' > at bci 6 for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown in interpreter method <{method} {0xffffffff68c4c8c8} 'invoke' '(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;' > at bci 56 for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown in interpreter method <{method} {0xffffffff69001af8} 'run' '()Z' in 'vm/mlvm/indy/func/jvmti/share/IndyRedefineTest'> at bci 65 for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown in interpreter method <{method} {0xffffffff69004588} 'runMlvmTest' '(Ljava/lang/Class;)Z' in 'vm/mlvm/share/MlvmTest'> at bci 113 for thread 0x0000000100112800 Exception <a 'java/lang/reflect/InvocationTargetException'> (0xfffffffe0063c7e8) thrown in interpreter method <{method} {0xffffffff69004588} 'runMlvmTest' '(Ljava/lang/Class;)Z' in 'vm/mlvm/share/MlvmTest'> at bci 147 for thread 0x0000000100112800 Exception <a 'java/lang/ClassNotFoundException'> (0xfffffffe0063ce20) thrown in interpreter method <{method} {0xffffffff68e7f8c8} 'run' '()Ljava/lang/Class;' in 'java/net/URLClassLoader$1'> at bci 72 for thread 0x0000000100112800 Exception <a 'java/lang/ClassNotFoundException'> (0xfffffffe0063ce20) thrown in interpreter method <{method} {0xffffffff68e7f978} 'run' '()Ljava/lang/Object;' in 'java/net/URLClassLoader$1'> at bci 1 for thread 0x0000000100112800 Exception <a 'java/security/PrivilegedActionException'> (0xfffffffe0063cfd8) thrown [/net/sc11152541/export/home/sspitsyn/hsx4/hotspot/src/share/vm/prims/jvm.cpp, line 1249] for thread 0x0000000100112800 Exception <a 'java/security/PrivilegedActionException'> (0xfffffffe0063cfd8) thrown in interpreter method <{method} {0xffffffff68cb66c8} 'doPrivileged' '(Ljava/security/PrivilegedExceptionAction;Ljava/secur> at bci 0 for thread 0x0000000100112800 Exception <a 'java/security/PrivilegedActionException'> (0xfffffffe0063cfd8) thrown in interpreter method <{method} {0xffffffff68d95bc8} 'findClass' '(Ljava/lang/String;)Ljava/lang/Class;' in 'java/net/URLC> at bci 13 for thread 0x0000000100112800 Exception <a 'java/lang/ClassNotFoundException'> (0xfffffffe0063ce20) thrown in interpreter method <{method} {0xffffffff68d95bc8} 'findClass' '(Ljava/lang/String;)Ljava/lang/Class;' in 'java/net/URLC> at bci 28 for thread 0x0000000100112800 Exception <a 'java/lang/ClassNotFoundException'> (0xfffffffe0063ce20) thrown in interpreter method <{method} {0xffffffff68c17c78} 'loadClass' '(Ljava/lang/String;Z)Ljava/lang/Class;' in 'java/lang/Cl> at bci 70 for thread 0x0000000100112800 Exception <a 'java/lang/ClassNotFoundException'> (0xfffffffe0063ce20) thrown in interpreter method <{method} {0xffffffff68c17c78} 'loadClass' '(Ljava/lang/String;Z)Ljava/lang/Class;' in 'java/lang/Cl> at bci 121 for thread 0x0000000100112800 Exception <a 'java/lang/ClassNotFoundException'> (0xfffffffe0063ce20) thrown in interpreter method <{method} {0xffffffff68c17c78} 'loadClass' '(Ljava/lang/String;Z)Ljava/lang/Class;' in 'java/lang/Cl> at bci 38 for thread 0x0000000100112800 #> #> WARNING: switching log to verbose mode, #> because error is complained #> Original bootstrap(): Lookup vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0; method name = greet; method type = (Object,String,int)Boolean # ERROR: Test caught an exception: . . .
10-10-2013
A fastdebug build with -XX:+TraceExceptions might help.
10-10-2013
The only asserts in the java.lang.invoke.MemberName$Factory class are in the method resolve(): /** Produce a resolved version of the given member. * Super types are searched (for inherited members) if {@code searchSupers} is true. * Access checking is performed on behalf of the given {@code lookupClass}. * If lookup fails or access is not permitted, null is returned. * Otherwise a fresh copy of the given member is returned, with modifier bits filled in. */ private MemberName resolve(byte refKind, MemberName ref, Class<?> lookupClass) { MemberName m = ref.clone(); // JVM will side-effect the ref assert(refKind == m.getReferenceKind()); try { m = MethodHandleNatives.resolve(m, lookupClass); m.checkForTypeAlias(); m.resolution = null; } catch (LinkageError ex) { // JVM reports that the "bytecode behavior" would get an error assert(!m.isResolved()); m.resolution = ex; return m; } assert(m.referenceKindIsConsistent()); m.initResolved(true); assert(m.vminfoIsConsistent()); return m; } Probably, one of the asserts above is the root cause of the issue. It'd be nice to identify which one and prove this rough guess. I'm trying to provide to Vladimir as much info as possible in hope, it is useful. But the ball currently has been moved to the Compiler team. :)
10-10-2013
Thanks, David. It is more clear now. Enabling the assertions in the MemberName code causes one of the asserts to fire which causes the test to fail. It throws an exception which is, most likely the root cause of the failure. Not sure yet if it is this one (it is not in the MemberName class but can be some consequences): # ERROR: java.lang.reflect.InvocationTargetException # ERROR: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) # ERROR: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) # ERROR: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) # ERROR: at java.lang.reflect.Method.invoke(Method.java:491) # ERROR: at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.run(IndyRedefineTest.java:25) # ERROR: at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:225) # ERROR: at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:141) # ERROR: at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:111) # ERROR: at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.main(IndyRedefineTest.java:39)
09-10-2013
Mystery solved: static {}; Code: 0: ldc #1 // class java/lang/invoke/MemberName 2: invokevirtual #54 // Method java/lang/Class.desiredAssertionStatus:()Z 5: ifne 12 8: iconst_1 9: goto 13 12: iconst_0 13: putstatic #28 // Field $assertionsDisabled:Z 16: new #55 // class java/lang/invoke/MemberName$Factory 19: dup 20: invokespecial #56 // Method "<init>":()V 23: putstatic #57 // Field INSTANCE:Ljava/lang/invoke/MemberName$Factory; 26: ldc #58 // int 983040 28: putstatic #3 // Field ALLOWED_FLAGS:I 31: return So why does this code exist? There is a quirky rule about assertion status that the status of a top-level class has to be determined at the earlier of the initialization of the class, or the initialization of any nested type in that class: http://docs.oracle.com/javase/specs/jls/se7/html/jls-14.html#jls-14.10 so here we can see that javac has inserted bytecode to force the determination of the assertion status of the MemberName class at the start of the clinit for the nested Factory class.
09-10-2013
Thanks, David. Apparently, the spec states that the assertions are enabled before the initialization method (<clinit>) execution: 8. Next, determine whether assertions are enabled for C by querying its defining class loader. 9. Next, execute the class or interface initialization method of C. But in the call stack the assertions are checked in the <clinit>(). It'd make sense to look into the <clinit> bytecodes.
09-10-2013
The JVMS states when the assertion status of a class is checked as part of the initialization sequence: http://docs.oracle.com/javase/specs/jvms/se7/html/jvms-5.html#jvms-5.5 8. Next, determine whether assertions are enabled for C by querying its defining class loader. But the initialization code in instanceKlass::initialize_impl does not match up with the numbering in JVMS any more and I can not see the point where the assertion status should be checked. It should be before the static initializer is actually executed - as it affects assertions in the static initializer. The code related to java assertion status is in javaAssertions.cpp but I can't make the links between class initialization and use of this code.
09-10-2013
This issue is reproducible only (as far as I currently know) with the flag -esa. It can be a reason to lower the priority of the bug to P4.
09-10-2013
I wonder if this issue can be related to the: https://bugs.openjdk.java.net/browse/JDK-8022701
09-10-2013
I've not found how the java.lang.Class.desiredAssertionStatus() is called from both: java.lang.invoke.MemberName$Factory.<clinit>() and java.lang.invoke.MethodHandleImpl.<clinit>(). So that it is tricky to see what are the manipulations with the boolean results of the calls. Apparently, these manipulations causes the test to fail. This code belongs to the Compiler team. I'm temporarily moving this issue to the hotspot/compiler category for evaluation of the problem. Feel free to move it back to the hotspot/jvmti category if you think it is the JVMTI issue. At least, I hope to get some details on: - the mechanism that is used to make the calls to the desiredAssertionStatus() - how the returning boolean value is used after the calls (what changes does it enforce?)
09-10-2013
This is the log when the test is failing (it is not intermittent): MY_TRACE: JavaAssertions::enabled: class name: java/lang/invoke/MethodType, sysClass: 1 MY_TRACE: JavaAssertions::enabled: class name: java/lang/invoke/MethodTypeForm, sysClass: 1 - IndyRedefineClass.c, 37: Setting redefined class name to vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0 - IndyRedefineClass.c, 31: Setting redefine trigger method name to redefineNow - IndyRedefineClass.c, 109: Entering redefine tigger method: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0;.redefineNow - IndyRedefineClass.c, 117: Redefining class vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0 # info :: File = /net/sqenfs-1.us.oracle.com/export1/comp/vm/testbase/sqe/vm/8/build/execution/vm/bin/newclass/vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0.class # info **Agent:: opening file /net/sqenfs-1.us.oracle.com/export1/comp/vm/testbase/sqe/vm/8/build/execution/vm/bin/newclass/vm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0.class # info file size= 3394 File red completely - IndyRedefineClass.c, 71: Enabling single step - IndyRedefineClass.c, 80: Forcing early return - IndyRedefineClass.c, 145: Single step event: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0; .target :3 - IndyRedefineClass.c, 71: Enabling single step - IndyRedefineClass.c, 76: Popping a frame - IndyRedefineClass.c, 145: Single step event: Ljava/lang/invoke/LambdaForm$DMH; .invokeStatic_LLI_L :e - IndyRedefineClass.c, 65: Disabling single step - IndyRedefineClass.c, 109: Entering redefine tigger method: Lvm/mlvm/indy/func/jvmti/mergeCP_indy2none_b/INDIFY_Dummy0;.redefineNow - IndyRedefineClass.c, 113: Class is already redefined. #> #> WARNING: switching log to verbose mode, #> because error is complained #> Original bootstrap(): Lookup vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0; method name = greet; method type = (Object,String,int)Boolean # ERROR: Test caught an exception: # ERROR: java.lang.reflect.InvocationTargetException # ERROR: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) # ERROR: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) # ERROR: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) # ERROR: at java.lang.reflect.Method.invoke(Method.java:491) # ERROR: at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.run(IndyRedefineTest.java:25) # ERROR: at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:225) # ERROR: at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:141) # ERROR: at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:111) # ERROR: at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.main(IndyRedefineTest.java:39) # ERROR: Caused by: java.lang.RuntimeException: Original target method was called. Test failed. # ERROR: at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.null(Unknown Source) # ERROR: at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.null(Unknown Source) # ERROR: at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget(Unknown Source) # ERROR: ... 9 more # ERROR: Test caught an exception: # ERROR: java.lang.RuntimeException # ERROR: at vm.mlvm.share.MlvmTest.throwAsUnckechedException(MlvmTest.java:184) # ERROR: at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:236) # ERROR: at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:141) # ERROR: at vm.mlvm.share.MlvmTest.launch(MlvmTest.java:111) # ERROR: at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.main(IndyRedefineTest.java:39) # ERROR: Caused by: java.lang.reflect.InvocationTargetException # ERROR: at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) # ERROR: at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) # ERROR: at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) # ERROR: at java.lang.reflect.Method.invoke(Method.java:491) # ERROR: at vm.mlvm.indy.func.jvmti.share.IndyRedefineTest.run(IndyRedefineTest.java:25) # ERROR: at vm.mlvm.share.MlvmTest.runMlvmTest(MlvmTest.java:225) # ERROR: ... 3 more # ERROR: Caused by: java.lang.RuntimeException: Original target method was called. Test failed. # ERROR: at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.null(Unknown Source) # ERROR: at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.null(Unknown Source) # ERROR: at vm.mlvm.indy.func.jvmti.mergeCP_indy2none_b.INDIFY_Dummy0.invokeTarget(Unknown Source) # ERROR: ... 9 more ### TRACE 1: TEST FAILED
09-10-2013
The following is the hack that makes the issue to disappear: hg diff src/share/vm/classfile/javaAssertions.cpp diff -r ac9cb1d5a202 src/share/vm/classfile/javaAssertions.cpp --- a/src/share/vm/classfile/javaAssertions.cpp Mon Oct 07 12:20:28 2013 -0400 +++ b/src/share/vm/classfile/javaAssertions.cpp Tue Oct 08 22:28:43 2013 -0700 @@ -210,5 +210,19 @@ bool JavaAssertions::enabled(const char* // No match. Return the default status. bool result = systemClass ? systemClassDefault() : userClassDefault(); trace(classname, systemClass ? "system" : "user", "default", result); + + static int HACKcnt = 0; // TMP HACK + if (0 == strcmp(classname, "java/lang/invoke/MemberName")) { + // The condition below demonstrates how the bug JDK-8023004 is triggered: + printf("HACK: JavaAssertions::enabled: classname: %s, systemClass: %d\n", classname, systemClass); + if (++HACKcnt == 2) { + // Returning result from 2nd call with same MemberName classname triggers the issue. + // Return 'false' instead of 'true' to make the issue to disappear. + result = false; + // Uncomment two lines below to get a crash with the call stack: + // char* bad = (char*) 159; + // *bad = 'x'; + } + } return result; } It is still interesting to find out what is the real cause though. :) The answer is somewhere in the code (or context) of the java.lang.invoke.MemberName$Factory.<clinit>.
09-10-2013
There are two calls to the JavaAssertions::enabled with the name of java/lang/invoke/MemberName in place of the 1st argument. Results of this second call triggers the failure: artificial return of 'false' instead of usual 'true' disables the issue. The call stack is: V [libjvm.so+0x6e6d44] bool JavaAssertions::enabled(const char*,bool)+0x134 V [libjvm.so+0x80b464] JVM_DesiredAssertionStatus+0x1d4 j java.lang.Class.desiredAssertionStatus0(Ljava/lang/Class;)Z+-1501629488 j java.lang.Class.desiredAssertionStatus0(Ljava/lang/Class;)Z+0 j java.lang.Class.desiredAssertionStatus()Z+10 j java.lang.invoke.MemberName$Factory.<clinit>()V+2 v ~StubRoutines::call_stub V [libjvm.so+0x6e9c28] void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0xa58 V [libjvm.so+0x67d7b4] void InstanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*)+0xd4 V [libjvm.so+0x67c0a4] void InstanceKlass::initialize_impl(instanceKlassHandle,Thread*)+0x63c V [libjvm.so+0x67aec8] void InstanceKlass::initialize(Thread*)+0x38 V [libjvm.so+0x997024] void LinkResolver::resolve_field(fieldDescriptor&,KlassHandle,Symbol*,Symbol*,KlassHandle,Bytecodes::Code,bool,bool,Thread*)+0x198 V [libjvm.so+0x996e84] void LinkResolver::resolve_field_access(fieldDescriptor&,constantPoolHandle,int,Bytecodes::Code,Thread*)+0x20c V [libjvm.so+0x6d22e4] void InterpreterRuntime::resolve_get_put(JavaThread*,Bytecodes::Code)+0x1dc j java.lang.invoke.MethodHandleImpl.initStatics()V+0 j java.lang.invoke.MethodHandleNatives.<clinit>()V+34 v ~StubRoutines::call_stub V [libjvm.so+0x6e9c28] void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0xa58 V [libjvm.so+0x67d7b4] void InstanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*)+0xd4 V [libjvm.so+0x67c0a4] void InstanceKlass::initialize_impl(instanceKlassHandle,Thread*)+0x63c V [libjvm.so+0x67aec8] void InstanceKlass::initialize(Thread*)+0x38 V [libjvm.so+0x99768c] void LinkResolver::resolve_static_call(CallInfo&,KlassHandle&,Symbol*,Symbol*,KlassHandle,bool,bool,Thread*)+0xbc V [libjvm.so+0x99df20] void LinkResolver::resolve_invokestatic(CallInfo&,constantPoolHandle,int,Thread*)+0x200 V [libjvm.so+0x99da5c] void LinkResolver::resolve_invoke(CallInfo&,Handle,constantPoolHandle,int,Bytecodes::Code,Thread*)+0x94c V [libjvm.so+0x6d51a8] void InterpreterRuntime::resolve_invoke(JavaThread*,Bytecodes::Code)+0x938 j java.lang.invoke.MemberName.<init>(Ljava/lang/reflect/Method;Z)V+11 j java.lang.invoke.MemberName.<init>(Ljava/lang/reflect/Method;)V+3 j java.lang.invoke.LambdaForm$NamedFunction.<init>(Ljava/lang/reflect/Method;)V+6 j java.lang.invoke.MethodHandleImpl.<clinit>()V+42 v ~StubRoutines::call_stub V [libjvm.so+0x6e9c28] void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0xa58 V [libjvm.so+0x67d7b4] void InstanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*)+0xd4 V [libjvm.so+0x67c0a4] void InstanceKlass::initialize_impl(instanceKlassHandle,Thread*)+0x63c V [libjvm.so+0x67aec8] void InstanceKlass::initialize(Thread*)+0x38 V [libjvm.so+0x99768c] void LinkResolver::resolve_static_call(CallInfo&,KlassHandle&,Symbol*,Symbol*,KlassHandle,bool,bool,Thread*)+0xbc V [libjvm.so+0x99df20] void LinkResolver::resolve_invokestatic(CallInfo&,constantPoolHandle,int,Thread*)+0x200 V [libjvm.so+0x99da5c] void LinkResolver::resolve_invoke(CallInfo&,Handle,constantPoolHandle,int,Bytecodes::Code,Thread*)+0x94c V [libjvm.so+0x6d51a8] void InterpreterRuntime::resolve_invoke(JavaThread*,Bytecodes::Code)+0x938 j java.lang.invoke.MethodHandle.<clinit>()V+16 v ~StubRoutines::call_stub V [libjvm.so+0x6e9c28] void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0xa58 V [libjvm.so+0x67d7b4] void InstanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*)+0xd4 V [libjvm.so+0x67c0a4] void InstanceKlass::initialize_impl(instanceKlassHandle,Thread*)+0x63c V [libjvm.so+0x67aec8] void InstanceKlass::initialize(Thread*)+0x38 V [libjvm.so+0xccc3fc] int Threads::create_vm(JavaVMInitArgs*,bool*)+0xfa4 V [libjvm.so+0x79dc9c] JNI_CreateJavaVM+0x94 C [libjli.so+0x6c60] JavaMain+0x140
09-10-2013
Thanks, guys! The issue is reproducible with the -esa flag. The -esa flag sets the JavaAssertions::_sysDefault assertion mode value that is used as the default return value in the: bool JavaAssertions::enabled(const char* classname, bool systemClass); This Hotspot function is called from the java.lang.Class.desiredAssertionStatus0() via the JVM_DesiredAssertionStatus API(). I've tracked down the exact class that causes this failure. It is the java/lang/invoke/MemberName. Below is the call stack when the JavaAssertions::_sysDefault value is retrieved as the default: V [libjvm.so+0x6e6d18] bool JavaAssertions::enabled(const char*,bool)+0x108 V [libjvm.so+0x80b43c] JVM_DesiredAssertionStatus+0x1d4 j java.lang.Class.desiredAssertionStatus0(Ljava/lang/Class;)Z+-1501629488 j java.lang.Class.desiredAssertionStatus0(Ljava/lang/Class;)Z+0 j java.lang.Class.desiredAssertionStatus()Z+10 j java.lang.invoke.MemberName.<clinit>()V+2 v ~StubRoutines::call_stub V [libjvm.so+0x6e9c00] void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0xa58 V [libjvm.so+0x67d7b4] void InstanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*)+0xd4 V [libjvm.so+0x67c0a4] void InstanceKlass::initialize_impl(instanceKlassHandle,Thread*)+0x63c V [libjvm.so+0x67aec8] void InstanceKlass::initialize(Thread*)+0x38 V [libjvm.so+0x6cc098] void InterpreterRuntime::_new(JavaThread*,ConstantPool*,int)+0x540 j java.lang.invoke.LambdaForm$NamedFunction.<init>(Ljava/lang/reflect/Method;)V+1 j java.lang.invoke.MethodHandleImpl.<clinit>()V+42 v ~StubRoutines::call_stub V [libjvm.so+0x6e9c00] void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0xa58 V [libjvm.so+0x67d7b4] void InstanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*)+0xd4 V [libjvm.so+0x67c0a4] void InstanceKlass::initialize_impl(instanceKlassHandle,Thread*)+0x63c V [libjvm.so+0x67aec8] void InstanceKlass::initialize(Thread*)+0x38 V [libjvm.so+0x997664] void LinkResolver::resolve_static_call(CallInfo&,KlassHandle&,Symbol*,Symbol*,KlassHandle,bool,bool,Thread*)+0xbc V [libjvm.so+0x99def8] void LinkResolver::resolve_invokestatic(CallInfo&,constantPoolHandle,int,Thread*)+0x200 V [libjvm.so+0x99da34] void LinkResolver::resolve_invoke(CallInfo&,Handle,constantPoolHandle,int,Bytecodes::Code,Thread*)+0x94c V [libjvm.so+0x6d51a8] void InterpreterRuntime::resolve_invoke(JavaThread*,Bytecodes::Code)+0x938 j java.lang.invoke.MethodHandle.<clinit>()V+16 v ~StubRoutines::call_stub V [libjvm.so+0x6e9c00] void JavaCalls::call_helper(JavaValue*,methodHandle*,JavaCallArguments*,Thread*)+0xa58 V [libjvm.so+0x67d7b4] void InstanceKlass::call_class_initializer_impl(instanceKlassHandle,Thread*)+0xd4 V [libjvm.so+0x67c0a4] void InstanceKlass::initialize_impl(instanceKlassHandle,Thread*)+0x63c V [libjvm.so+0x67aec8] void InstanceKlass::initialize(Thread*)+0x38 V [libjvm.so+0xccc3dc] int Threads::create_vm(JavaVMInitArgs*,bool*)+0xfa4 V [libjvm.so+0x79dc74] JNI_CreateJavaVM+0x94 C [libjli.so+0x6c60] JavaMain+0x140 Then the java.lang.invoke.MemberName class uses this value in some way that causes this failure. Now I'm trying to understand what is the exact issue there.
09-10-2013
I guess, this issue was resolved by the fix of: https://bugs.openjdk.java.net/browse/INTJDK-7604059
07-10-2013
I'm going to close this bug as "Can not reproduce" if this issue did not shown up in the Comp baseline for the last month. Still waiting for the Aurora unplanned outage to complete.
07-10-2013
The Aurora is not available from yesterday.
07-10-2013
Is it possible the Comp baseline is using a different SQE testbase release than the PIT and Promo testing? I can not reproduce this issue in thousand of runs. It is possible that it is really gone. I'll check the Comp baseline history.
07-10-2013