Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

JDK18 DaaLoadTest FAILED - Cannot invoke "jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl #14395

Closed
JasonFengJ9 opened this issue Jan 28, 2022 · 44 comments · Fixed by #14688

Comments

@JasonFengJ9
Copy link
Member

JasonFengJ9 commented Jan 28, 2022

Failure link

From an internal build job/Test_openjdk18_j9_special.system_aarch64_linux_testList_0/6/(ub18-aarch64-7):

openjdk version "18-ea" 2022-03-22
IBM Semeru Runtime Open Edition 18.0.0.0 (build 18-ea+32)
Eclipse OpenJ9 VM 18.0.0.0 (build master-5e9bd4ea0, JRE 18 Linux aarch64-64-Bit Compressed References 20220127_21 (JIT enabled, AOT enabled)
OpenJ9   - 5e9bd4ea0
OMR      - 4a009d2fe
JCL      - 0764ffcb69 based on jdk-18+32)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

[2022-01-27T06:22:16.660Z] Running test DaaLoadTest_daa2_special_5m_27 ...
[2022-01-27T06:22:16.660Z] ===============================================

[2022-01-27T06:22:16.660Z] variation: Mode612-OSRG
[2022-01-27T06:22:16.660Z] JVM_OPTIONS:  -Xcompressedrefs -Xgcpolicy:gencon -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation 

[2022-01-27T06:24:52.442Z] DLT 01:24:49.081 - Test failed
[2022-01-27T06:24:52.443Z] DLT   Failure num.  = 1
[2022-01-27T06:24:52.443Z] DLT   Test number   = 15
[2022-01-27T06:24:52.443Z] DLT   Test details  = 'JUnit[net.openj9.test.binaryData.TestInteger2ByteArray]'
[2022-01-27T06:24:52.443Z] DLT   Suite number  = 0
[2022-01-27T06:24:52.443Z] DLT   Thread number = 0
[2022-01-27T06:24:52.443Z] DLT >>> Captured test output >>>

[2022-01-27T06:24:52.443Z] DLT testFailure: testNullByteArrayLittleEndian(net.openj9.test.binaryData.TestInteger2ByteArray): Unexpected exception, expected<java.lang.NullPointerException> but was<java.lang.IllegalArgumentException>
[2022-01-27T06:24:52.443Z] DLT java.lang.Exception: Unexpected exception, expected<java.lang.NullPointerException> but was<java.lang.IllegalArgumentException>
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:28)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.Suite.runChild(Suite.java:128)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.Suite.runChild(Suite.java:27)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[2022-01-27T06:24:52.443Z] DLT 	at net.adoptopenjdk.loadTest.adaptors.JUnitAdaptor.executeTest(JUnitAdaptor.java:130)
[2022-01-27T06:24:52.443Z] DLT 	at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
[2022-01-27T06:24:52.443Z] DLT 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
[2022-01-27T06:24:52.443Z] DLT 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[2022-01-27T06:24:52.443Z] DLT 	at java.base/java.lang.Thread.run(Thread.java:884)
[2022-01-27T06:24:52.443Z] DLT Caused by: java.lang.IllegalArgumentException: java.lang.NullPointerException: Cannot invoke "jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.lang.Object, java.lang.Object[])" because "this" is null
[2022-01-27T06:24:52.443Z] DLT 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:114)
[2022-01-27T06:24:52.443Z] DLT 	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[2022-01-27T06:24:52.443Z] DLT 	at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:19)
[2022-01-27T06:24:52.443Z] DLT 	... 26 more
[2022-01-27T06:24:52.443Z] DLT Caused by: java.lang.NullPointerException: Cannot invoke "jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.lang.Object, java.lang.Object[])" because "this" is null
[2022-01-27T06:24:52.443Z] DLT 	at java.base/java.lang.invoke.LambdaForm$MH/0x00000000b8240210.invokeExact_MT(LambdaForm$MH)
[2022-01-27T06:24:52.443Z] DLT 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:154)
[2022-01-27T06:24:52.443Z] DLT 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
[2022-01-27T06:24:52.443Z] DLT 	... 32 more

[2022-01-27T06:24:52.444Z] DaaLoadTest_daa2_special_5m_27_FAILED

50x grinder - job/Grinder/20524/ - 49/50 failed.
50x grinder w/ -Xint - job/Grinder/20610/

@pshipton
Copy link
Member

pshipton commented Feb 11, 2022

Internal test (0.31 m1) /job/Test_openjdk18_j9_special.system_ppc64_aix_testList_2/8
DaaLoadTest_daa2_special_5m_19

variation: Mode607
JVM_OPTIONS: -Djava.security.manager=allow 
DLT testFailure: testNullByteArray(net.openj9.test.binaryData.TestByteArray2Float): Unexpected exception, expected<java.lang.NullPointerException> but was<java.lang.IllegalArgumentException>
DLT java.lang.Exception: Unexpected exception, expected<java.lang.NullPointerException> but was<java.lang.IllegalArgumentException>
DLT 	at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:28)
DLT 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
DLT 	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
DLT 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
DLT 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
DLT 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
DLT 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
DLT 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
DLT 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
DLT 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
DLT 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
DLT 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
DLT 	at org.junit.runners.Suite.runChild(Suite.java:128)
DLT 	at org.junit.runners.Suite.runChild(Suite.java:27)
DLT 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
DLT 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
DLT 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
DLT 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
DLT 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
DLT 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
DLT 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
DLT 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
DLT 	at net.adoptopenjdk.loadTest.adaptors.JUnitAdaptor.executeTest(JUnitAdaptor.java:130)
DLT 	at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
DLT 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
DLT 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
DLT 	at java.base/java.lang.Thread.run(Thread.java:889)
DLT Caused by: java.lang.IllegalArgumentException: java.lang.NullPointerException: Cannot invoke "jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.lang.Object, java.lang.Object[])" because "this" is null
DLT 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:114)
DLT 	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
DLT 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
DLT 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
DLT 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
DLT 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
DLT 	at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:19)
DLT 	... 26 more
DLT Caused by: java.lang.NullPointerException: Cannot invoke "jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.lang.Object, java.lang.Object[])" because "this" is null
DLT 	at java.base/java.lang.invoke.LambdaForm$MH/0x00000000230581b0.invokeExact_MT(LambdaForm$MH)
DLT 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:154)
DLT 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
DLT 	... 32 more

/job/Test_openjdk18_j9_special.system_ppc64le_linux_testList_1/8
DaaLoadTest_daa2_special_5m_21

variation: Mode615
JVM_OPTIONS: -Djava.security.manager=allow 

testFailure: testNegativeNumBytesBigEndian(net.openj9.test.binaryData.TestInteger2ByteArrayNumBytes)

@pshipton pshipton changed the title JDK18 DaaLoadTest_FAILED - testNullByteArrayLittleEndian: expected<java.lang.NullPointerException> but was<java.lang.IllegalArgumentException> JDK18 DaaLoadTest FAILED - Cannot invoke "jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl Feb 11, 2022
@pshipton
Copy link
Member

pshipton commented Feb 22, 2022

There are a lot of these failures in the jdk18 special.system build on all platforms, I'm setting as a blocker.
https://openj9-jenkins.osuosl.org/job/Pipeline-Build-Test-JDK18/17/
https://openj9-jenkins.osuosl.org/job/Pipeline-Build-Test-JDK18/16/

Subset of failure modes, some are the default modes. I didn't list the failures for all platforms, see the build links above.

xlinux:
DaaLoadTest_daa2_special_5m_26
DaaLoadTest_daa2_special_5m_17
DaaLoadTest_all_special_5m_17

zlinux:
DaaLoadTest_all_special_5m_17
DaaLoadTest_daa2_special_5m_21
DaaLoadTest_daa2_special_5m_17
DaaLoadTest_all_special_5m_21

mac:
DaaLoadTest_all_special_5m_27
DaaLoadTest_daa2_special_5m_26
DaaLoadTest_all_special_5m_21
DaaLoadTest_daa2_special_5m_21
DaaLoadTest_daa2_special_5m_0
DaaLoadTest_daa2_special_5m_8
DaaLoadTest_all_special_5m_26

alinux:
DaaLoadTest_daa2_special_5m_25
DaaLoadTest_all_special_5m_1
DaaLoadTest_all_special_5m_21
DaaLoadTest_all_special_5m_25
DaaLoadTest_daa2_special_5m_21
DaaLoadTest_daa2_special_5m_26
DaaLoadTest_daa2_special_5m_27
DaaLoadTest_all_special_5m_26

@vij-singh
Copy link

@0xdaryl Any suggestions for somebody to triage?

@0xdaryl
Copy link
Contributor

0xdaryl commented Feb 22, 2022

@nbhuiyan : could you triage these failures please? There seem to similar failures across platforms, so please pick whichever platform you are most comfortable with.

@nbhuiyan nbhuiyan self-assigned this Feb 22, 2022
@nbhuiyan
Copy link
Member

This test failure can be easily reproduced locally. This issue has shown up as a result of of JDK18 using method handles for reflection (JEP 416). The failure can be avoided by disabling MH usage in reflection using -Djdk.reflect.useDirectMethodHandle=false. It is also not reproducible using -Xint. The failure happens in the second invocation of DirectMethodHanldeAccessor.invoke(Object, Object[]), so it requires the method to be compiled for the crash to take place.

The IllegalArgumentException originates from here. Trying to call invokeImpl a few lines above results in an NPE, which then gets wrapped in the IllegalArgumentException, and that's what we see in the error outputs above. While the test expects an NPE, this is not where the NPE should have occurred due to the null byte array in the test case, and therefore that exception handler should not have been involved at all. I am examining the JIT logs and the compiled code to see why this is happening.

@nbhuiyan
Copy link
Member

Having examined the JIT logs and the compiled code for the caller of the invokeImpl method (DirectMethodHandleAccessor.invoke()) did not reveal any obvious issues. We can also rule out the possibility of premature GC-ing as this failure is reproducible with GC disabled and the VM configured with a large enough max heap size.

Forcing DirectMethodHandleAccessor.invoke() to compile with optLevel=noOpt avoids the failure. We need to allow inlining to happen for this failure to occur, and I narrowed down to just one method that we must inline to reproduce the failure, which is DirectMethodHanldeAccessor.invokeImpl(). However, if invokeImpl() is JIT-ed separately instead of being inlined in its calling method, the failure does not occur. I am continuing down this path and will post an update on my findings.

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 1, 2022

Even with every optimization disabled, inlining invokeImpl() results in the test failure. I could not identify any functional issues so far during IL generation, codegen or runtime for the problematic method so far, and may likely require more time to identify the underlying cause. However, I do have a temporary workaround in place where we skip inlining invokeImpl(). This workaround does not result in measurable performance degradation, based on running the benchmarks in ReflectionSpeedBenchmark.java. I am currently testing the workaround on all platforms to verify all the failed tests reported in this issue passes. I will open a PR with the workaround after the tests pass.

@0xdaryl
Copy link
Contributor

0xdaryl commented Mar 1, 2022

The IllegalArgumentException originates from here. Trying to call invokeImpl a few lines above results in an NPE, which then gets wrapped in the IllegalArgumentException,

Are you suggesting then that invokeImpl() throws an NPE unexpectedly because it is caught and rethrown as an IAE? Meaning, our focus is on invokeImpl() to determine why it threw an NPE and not the exception throw/catch/stackwalker mechanism.

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 1, 2022

invokeImpl throws an NPE while trying to call target.invokeExact (case 0) , which is then caught and re-thrown as IAE later. Yes, our focus needs to be only on invokeImpl, and determining why it throws the NPE in the first place.

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 8, 2022

I have continued my investigation of this issue over the past week. My investigation over the last week involved trying to run the test in a debugger, with a break inserted at at the start of DirectMethodHandleAccessor.invoke in an attempt to land there right before the NPE is thrown. However, the problem was not reproducible in a debugger.

@jdmpapin , and I investigated cores obtained via -Xdump, configured using -Xdump:java+system:events=throw,filter=java/lang/NullPointerException#jdk/internal/reflect/DirectMethodHandleAccessor.invokeImpl,range=1..1

The error reported:

testFailure: testNullByteArray(net.openj9.test.binaryData.TestShort2ByteArrayNumBytes): Unexpected exception, expected<java.lang.NullPointerException> but was<java.lang.IllegalArgumentException>
java.lang.Exception: Unexpected exception, expected<java.lang.NullPointerException> but was<java.lang.IllegalArgumentException>
	at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:28)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
        ...
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:889)
Caused by: java.lang.IllegalArgumentException: java.lang.NullPointerException: Cannot invoke "java.lang.invoke.MethodHandle.invokeExact(java.lang.Object)"
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:139)
	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:19)
	... 26 more

This NPE, when thrown in DirectMethodHandleAccessor.invokeImpl, should trigger the dump agent, and then get handled by the exception handling mechanism in DirectMethodHandleAccessor.invoke. When looking at the Java dump, the Current thread has a stack trace that indicates that the actual call stack had a few more levels of calls:

1XMCURTHDINFO  Current thread
3XMTHREADINFO      "load-5" J9VMThread:0x00000000005AF200, omrthread_t:0x00007F2AF45A5688, java/lang/Thread:0x0000000083E1A678, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x20, isDaemon:false)
3XMTHREADINFO1            (native thread ID:0x246EE7, native priority:0x5, native policy:UNKNOWN, vmstate:R, vm thread flags:0x00001020)
3XMTHREADINFO2            (native stack address range from:0x00007F2AD9533000, to:0x00007F2AD9573000, size:0x40000)
3XMCPUTIME               CPU usage total: 1.765418943 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at com/ibm/dataaccess/ByteArrayMarshaller.writeShort(ByteArrayMarshaller.java:58(Compiled Code))
4XESTACKTRACE                at net/openj9/test/binaryData/TestShort2ByteArrayNumBytes.testNullByteArray(TestShort2ByteArrayNumBytes.java:736(Compiled Code))
4XESTACKTRACE                at java/lang/invoke/LambdaForm$DMH/0x00000000f420a1c0.invokeVirtual(LambdaForm$DMH(Compiled Code))
4XESTACKTRACE                at java/lang/invoke/LambdaForm$MH/0x0000000060086fd0.invoke(LambdaForm$MH(Compiled Code))
4XESTACKTRACE                at java/lang/invoke/LambdaForm$MH/0x00000000f4209210.invokeExact_MT(LambdaForm$MH(Compiled Code))
4XESTACKTRACE                at jdk/internal/reflect/DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:173(Compiled Code))
4XESTACKTRACE                at jdk/internal/reflect/DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:115(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:577(Compiled Code))
4XESTACKTRACE                at org/junit/runners/model/FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/model/ReflectiveCallable.run(ReflectiveCallable.java:12(Compiled Code))
4XESTACKTRACE                at org/junit/runners/model/FrameworkMethod.invokeExplosively(FrameworkMethod.java:47(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/InvokeMethod.evaluate(InvokeMethod.java:17(Compiled Code))
4XESTACKTRACE                at org/junit/internal/runners/statements/ExpectException.evaluate(ExpectException.java:19(Compiled Code))

This meant that the NPE is not actually thrown in invokeImpl, but a few levels of calls later.

Looking at the java/lang/invoke/LambdaForm$MH/0x0000000060086fd0.invoke in the call stack, we found that the subsequent callees in the call stack were inlined in that LF generated method, all the way down to ByteArrayMarshaller.writeShort. It is from ByteArrayMarshaller.writeShort that the jitThrowNullPointerException helper is called. This is expected behaviour for calling the method with a null byte array (as the failing tests do), but what did not make sense was that the NPE should always end up back in DirectMethodHandleAccessor.invoke and result in the IllegalArgumentException being thrown, yet that is not the case with -Xint or if we prevent DirectMethodHandleAccessor.invokeImpl getting inlined, or any of the other methods (such as running in debugger) that manages to hide this behaviour. The NPE should have reached the last method in the call stack above (ExpectException.evaluate) for the test to succeed, but it gets changed to IAE in DirectMethodHandleAccessor.invoke.

Currently, we are working on narrowing down to the smallest set of methods we need to compile for the failure to happen, and continuing our investigation from there.

@vij-singh
Copy link

@nbhuiyan Any new news on the proposed workaround?

@0xdaryl
Copy link
Contributor

0xdaryl commented Mar 8, 2022

@vij-singh : the workaround proposed above just treats the symptom of the problem and not the cause. Unfortunately, we don't know the cause yet despite some heroic efforts to diagnose this. I'm not comfortable applying a workaround until we understand why it causes the problem to not occur.

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 8, 2022

@babsingh, @JasonFengJ9, since you were involved in the JEP 416 work, I was wondering if you could share some insight into the problem we are seeing here. In the JIT-ed code, the NPE is thrown in the inner-most frame in the stack trace in the Java core above, com/ibm/dataaccess/ByteArrayMarshaller.writeShort. In the outer call frames leading up to jdk/internal/reflect/DirectMethodHandleAccessor.invoke, there is nothing that the exception is supposed to be caught by, so there is no way that the NPE does not get handled by the catch block here. From what we have seen so far, this should be the behaviour we expect from the implementation of DirectMethodHandleAccessor.invoke, and the exception can't propagate out to the outer frameorg/junit/internal/runners/statements/ExpectException.evaluate without being changed into IAE, resulting in the test failing as it expects an NPE.

However, this IAE does not happen with -Xint. How is the interpreter bypassing the exception handler in DirectMethodHandleAccessor.invoke for it to reach the exception type check unchanged for the tests to pass? For the the failing tests in the interpreter mode, do we call a different set of methods if interpreted?

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 8, 2022

I did a little experiment by changing the code here
So I assigned the result of the invokeImpl call before returning:

before:

return invokeImpl(obj, args);

after:

Object result = invokeImpl(obj, args);
return result;

Now the tests fail 100% of the time for both the JIT and interpreter modes. This suggests that the JIT-ed code doing the right thing resulted in the test failure, and the test failure was actually because the new reflection code wants to throw an IAE for what the test case was doing. If that's the case, do the tests need to be updated to expect the IAE for JDK18+? However, I do not understand how the interpreter bypassed the exception handler in the first place.

@tajila
Copy link
Contributor

tajila commented Mar 8, 2022

@babsingh can you take a look at what Nazim mentioned above

@babsingh
Copy link
Contributor

babsingh commented Mar 8, 2022

do the tests need to be updated to expect the IAE for JDK18+?

The reflection API has not changed. The behaviour should be the same with JEP416 enabled.

The LambdaForm frames need to be hidden for AccessorUtils.isIllegalArgument to function correctly. #3627 hides those frames.

In #14395 (comment), I still see the frames which should have been hidden by #3627. In this case, the methods in the frames are compiled. @nbhuiyan Can you confirm if the difference between the interpreter and JIT paths is the absence of those frames? If so, follow on JIT changes will be needed to hide those frames when the methods are compiled.

@babsingh
Copy link
Contributor

babsingh commented Mar 9, 2022

@nbhuiyan Would know the location of the test source code: TestShort2ByteArrayNumBytes.testNullByteArray?

@babsingh
Copy link
Contributor

babsingh commented Mar 9, 2022

#3627 only does the changes in runtime/vm/swalk.c::walkFrame. We will need to do identical changes in runtime/codert_vm/jswalk.c. @gacholio Is this true? Are there any other locations where similar changes are needed to support the JIT?

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

No more changes are needed to the stack walkers - hopefully I would have caught that when I reviewed the code.

Do you have something specific in mind that I may have overlooked?

@babsingh
Copy link
Contributor

babsingh commented Mar 9, 2022

Do you have something specific in mind that I may have overlooked?

I assumed more changes are needed just by observation. In #14395 (comment), I still see the following hidden frames which should have been skipped by #3627:

4XESTACKTRACE                at java/lang/invoke/LambdaForm$DMH/0x00000000f420a1c0.invokeVirtual(LambdaForm$DMH(Compiled Code))
4XESTACKTRACE                at java/lang/invoke/LambdaForm$MH/0x0000000060086fd0.invoke(LambdaForm$MH(Compiled Code))
4XESTACKTRACE                at java/lang/invoke/LambdaForm$MH/0x00000000f4209210.invokeExact_MT(LambdaForm$MH(Compiled Code))

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 9, 2022

@babsingh

location of the test source code: TestShort2ByteArrayNumBytes.testNullByteArray

It is located in the openj9-systemtest repo: TestShort2ByteArrayNumBytes.testNullByteArray

There are many other testNullByteArrays in other classes in that directory where the failure can be observed.

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

All of the reporting goes via walkFrame, including inlined JIT frames, so I don't know why those would not be skipped if they're marked correctly.

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

I think there needs to be a similar change made to the exception backtrace decoder. The changes made only affect the walk of the stack - exception backtraces contain only a single PC for a compiled frame, which may contain any number of inlined frames.

The code as it stands would eliminate all of the frames if the outer method was marked, which would result in incorrectly missing frames if the inlined methods were not marked.

I think we need to remove the skip hidden frames option from exception backtrace creation and handle it in the backtrace decode logic.

@fengxue-IS
Copy link
Contributor

#3627 added a new stackwalk flag J9_STACKWALK_SKIP_HIDDEN_FRAMES which need to be specified to skip the hiddenframes, I have only added this flag for Java API's used to get exception stacktrace. if we expect the javacore info to also skip hiddenframes, then this flags should be added at the caller generating the dump

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

I would recommend against removing any frames from javacores - they need to be as detailed and accurate as possible.

@babsingh
Copy link
Contributor

babsingh commented Mar 9, 2022

@gacholio Can you point us to the code for backtrace decode logic?

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 9, 2022

@babsingh

The LambdaForm frames need to be hidden for AccessorUtils.isIllegalArgument to function correctly.

Looking at the implementation of isIllegalArgument, I am not sure I understand how the presence of LamdaForm frames is causing the test failures. It returns true or false and depending on that the exception that was caught in DirectMethodHandleAccessor.invoke would be rethrown as IllegalArgumentException or InvocationTargetException.

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

Remove the changes in BytecodeInterperer.hpp and add an option to check hidden here:

/*
* Walks the backtrace of an exception instance, invoking a user-supplied callback function for
* each frame on the call stack.
*
* @param vmThread
* @param exception The exception object that contains the backtrace.
* @param callback The callback function to be invoked for each stack frame.
* @param userData Opaque data pointer passed to the callback function.
* @param pruneConstructors Non-zero if constructors should be pruned from the stack trace.
* @return The number of times the callback function was invoked.
*
* @note Assumes VM access
**/
UDATA
iterateStackTrace(J9VMThread * vmThread, j9object_t* exception, callback_func_t callback, void * userData, UDATA pruneConstructors)

The other option is to leave the decode logic alone and add the check in the appropriate callers, but it seems cleaner to add the option here.

@fengxue-IS
Copy link
Contributor

The LambdaForm frames need to be hidden for AccessorUtils.isIllegalArgument to function correctly.

Looking at the implementation of isIllegalArgument, I am not sure I understand how the presence of LamdaForm frames is causing the test failures. It returns true or false and depending on that the exception that was caught in DirectMethodHandleAccessor.invoke would be rethrown as IllegalArgumentException or InvocationTargetException.

@nbhuiyan If you look at the impl of Junit's ReflectiveCallable.run here, the test code will unwrap the InvocationTargetException so the issue seem to be still isIllegalArgument returning true causing IAE. The correct stacktrace should return false in AccessorUtils.isIllegalArgument line 81

I dont see how -Xint could fail with the changes to invokeImpl as interpreter won't inline any method causing the issue Gac has pointed out.

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

The other option is to leave the decode logic alone and add the check in the appropriate callers, but it seems cleaner to add the option here.

The way iterateStackTrace is implemented (passing a NULL callback to get the count), I think the hidden test has to reside in the iterator and not the callers (or else the callback would have to be changed to return whether the frame "counts" or not).

@babsingh
Copy link
Contributor

babsingh commented Mar 9, 2022

re #14395 (comment):

now the tests fail 100% of the time for both the JIT and interpreter modes.

I did few experiments. With -Xint -Xshareclasses:none,noaot, I was able to stop the failure.

make _DaaLoadTest_daa2_special_5m_27 EXTRA_OPTIONS="-Xint -Xshareclasses:none,noaot" 

Afterwards, I was unable to reproduce the failure just with -Xint.

Other observations:

how the presence of LamdaForm frames is causing the test failures

In addition to Jack's justification in #14395 (comment), GAC's feedback in #14395 (comment) is also important. It suggests that AccessorUtils.isIllegalArgument will also malfunction if more frames are eliminated.

The code as it stands would eliminate all of the frames if the outer method was marked, which would result in incorrectly missing frames if the inlined methods were not marked.

The next step is to try GAC's suggestions: #14395 (comment), #14395 (comment) and #14395 (comment).

@jdmpapin
Copy link
Contributor

jdmpapin commented Mar 9, 2022

If the failure is caused by a bad interaction between hidden methods and JIT frames, -Xint should prevent the failure regardless of -Xshareclasses options, shouldn't it? With -Xint the JIT library isn't even loaded, so we should never have JIT frames

@babsingh
Copy link
Contributor

babsingh commented Mar 9, 2022

Test target: _DaaLoadTest_daa2_special_5m_27.

It's worth noting that the test is run with -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation. As per the discussion in #14014, it is an unusual mode.

The -Xint is appended after the above -Xjit option. May be this is not sufficient to completely disable the JIT? or #3627 may have other deficiencies? An investigation will be needed.

# Test Fails
# JVM options: -Xint -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation
export IBM_JAVA_OPTIONS=-Xint
make _DaaLoadTest_daa2_special_5m_27

# Test Passes
# JVM options: -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation -Xint
make _DaaLoadTest_daa2_special_5m_27  EXTRA_OPTIONS="-Xint"

# Test Passes
# JVM options: none
make _DaaLoadTest_daa2_special_5m_27 JVM_OPTIONS=""

# Test Passes
# JVM options: -Xint
make _DaaLoadTest_daa2_special_5m_27 JVM_OPTIONS="-Xint"

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

Rightmost option wins between -Xjit and -Xint so there should be no difference between the first and last runs above.

@jdmpapin
Copy link
Contributor

jdmpapin commented Mar 9, 2022

-Xjit:... -Xint does disable the JIT. Before writing my last comment, I confirmed that with -Xint we won't load the JIT library. The way that I confirmed that was by taking an existing Java command I had been running with an -Xjit option, and adding -Xint -Xdump:system:events=vmstop to the end. The loaded libraries in the core did not include libj9jit29.so

@nbhuiyan
Copy link
Member

nbhuiyan commented Mar 9, 2022

I realized that the way I set up my options did not disable the JIT as the -Xint appeared before -Xjit:..., so my comment above can be disregarded.

@babsingh
Copy link
Contributor

babsingh commented Mar 9, 2022

I also mixed my test runs with IBM_JAVA_OPTIONS which led to the -Xint failures because IBM_JAVA_OPTIONS are processed as the leftmost options and were overridden by the -Xjit option. With -Xint as the rightmost option, I also confirm that the failures don't happen. #14395 (comment) can be ignored.

@fengxue-IS
Copy link
Contributor

Given comments above, then the only case which fails is due to issue Gac has pointed out in #14395 (comment).
I will create a PR to address this.

@fengxue-IS
Copy link
Contributor

@gacholio should I also remove the changes to all fillInStackTrace in #3627? Do other paths face the same issue with JIT inlined methods

@fengxue-IS
Copy link
Contributor

I've also noticed that iterateStackTrace could be called during java core dump at

if (j9sig_protect(protectedIterateStackTrace,
, as per #14395 (comment), should the skip hidden frame flag be defined by caller of iterateStackTrace or does this case not affect the issue here

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

should the skip hidden frame flag be defined by caller of iterateStackTrace or does this case not affect the issue here

My feeling is that we should not skip hidden frames in the javacore, but others may have a different opinion. @tajila @keithc-ca

@gacholio
Copy link
Contributor

gacholio commented Mar 9, 2022

should I also remove the changes to all fillInStackTrace in #3627? Do other paths face the same issue with JIT inlined methods

Yes, all fillInStackTrace changes must be removed.

@keithc-ca
Copy link
Contributor

should the skip hidden frame flag be defined by caller of iterateStackTrace or does this case not affect the issue here

My feeling is that we should not skip hidden frames in the javacore, but others may have a different opinion.

For clarity, I agree with GAC's earlier comment that all stack frames should be included in javacore files.

@jdmpapin
Copy link
Contributor

jdmpapin commented Mar 9, 2022

The code as it stands would eliminate all of the frames if the outer method was marked, which would result in incorrectly missing frames if the inlined methods were not marked.

I just want to mention that I think this also explains why -Xdump was triggered when ByteArrayMarshaller.writeShort threw NPE even though the filter was looking for DirectMethodHandleAccessor.invokeImpl. The writeShort and testNullByteArray frames aren't supposed to be hidden, but they were inlined into a JIT frame for a LambdaForm-generated invoke. The next frame out was also LambdaForm-generated (invokeExact_MT). So the innermost frame in the exception's backtrace was invokeImpl, and then -Xdump was triggered because its filter looks at the exception's stack trace rather than the current stack when we throw. (Even if it looked at the current stack though, it might still have been triggered if it were to do so using the same hidden frame logic)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.