Closed M-Davies closed 2 years ago
This test is relying on unspecified details of the lambda implementation. I believe the OpenJ9 stack frame is correct, unless DumpStackTest$$Lambda$3.000000009FE08CD0.accept
should be a hidden frame.
@DanHeidinga do you concur?
openjdk_test_output (3).tar.gz Log file
Is it ok for me to close this @DanHeidinga if you're in agreement with Peter's comment?
What criteria is OpenJDK using to determine if the frame should be visible or not?
If it's that the class is loaded by Unsafe.defineAnonymousClass then OpenJ9 should mark those frames as invisible as well.
I think more investigation is needed here
I dig some digging using -Xdump:
Unsafe
loads MethodHandle
but not the .accept
frame. Neither Lambda
or DumpStackTest
are loaded using Unsafe
15:11:11 JVMDUMP039I Processing dump event "load", detail "jdk/internal/loader/URLClassPath$FileLoader$1" at 2019/09/06 14:11:08 - please wait.
15:11:11 JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0733.txt' in response to an event
15:11:11 JVMDUMP010I Java dump written to /home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0733.txt
15:11:11 JVMDUMP013I Processed dump event "load", detail "jdk/internal/loader/URLClassPath$FileLoader$1".
15:11:11 JVMDUMP039I Processing dump event "load", detail "DumpStackTest" at 2019/09/06 14:11:08 - please wait.
15:11:11 JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0734.txt' in response to an event
15:11:11 JVMDUMP010I Java dump written to /home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0734.txt
15:11:11 JVMDUMP013I Processed dump event "load", detail "DumpStackTest".
15:11:11 JVMDUMP039I Processing dump event "load", detail "DumpStackTest$1" at 2019/09/06 14:11:08 - please wait.
15:11:11 JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0735.txt' in response to an event
15:11:11 JVMDUMP010I Java dump written to /home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0735.txt
15:11:11 JVMDUMP013I Processed dump event "load", detail "DumpStackTest$1".
15:11:11 JVMDUMP039I Processing dump event "load", detail "DumpStackTest$CallFrame" at 2019/09/06 14:11:08 - please wait.
15:11:11 JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0736.txt' in response to an event
15:11:11 JVMDUMP010I Java dump written to /home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141108.29549.0736.txt
15:11:11 JVMDUMP013I Processed dump event "load", detail "DumpStackTest$CallFrame".
And later...
15:11:11 JVMDUMP039I Processing dump event "load", detail "DumpStackTest$$Lambda$3/0000000000000000" at 2019/09/06 14:11:10 - please wait.
15:11:11 JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141110.29549.0828.txt' in response to an event
15:11:11 JVMDUMP010I Java dump written to /home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141110.29549.0828.txt
15:11:11 JVMDUMP013I Processed dump event "load", detail "DumpStackTest$$Lambda$3/0000000000000000".
15:11:11 java.lang.RuntimeException: StackTraceElements mismatch at index 3. Expected [DumpStackTest.testLambda(DumpStackTest.java)], but get [DumpStackTest$$Lambda$3.0000000000000000.accept(Unknown Source)]
15:11:11 at DumpStackTest.assertEquals(DumpStackTest.java:227)
15:11:11 at DumpStackTest.assertStackTrace(DumpStackTest.java:219)
15:11:11 at DumpStackTest.consumeLambda(DumpStackTest.java:147)
15:11:11 at DumpStackTest.lambda$testLambda$0(DumpStackTest.java:129)
15:11:11 at DumpStackTest$$Lambda$3.0000000000000000.accept(Unknown Source)
15:11:11 at DumpStackTest.testLambda(DumpStackTest.java:130)
15:11:11 at DumpStackTest.main(DumpStackTest.java:45)
15:11:11 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
15:11:11 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
15:11:11 at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
15:11:11 at java.base/java.lang.reflect.Method.invoke(Method.java:566)
15:11:11 at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
15:11:11 at java.base/java.lang.Thread.run(Thread.java:831)
15:11:11 JVMDUMP039I Processing dump event "load", detail "java/util/Collections$EmptyIterator" at 2019/09/06 14:11:10 - please wait.
15:11:11 JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141110.29549.0829.txt' in response to an event
15:11:11 JVMDUMP010I Java dump written to /home/jenkins/workspace/Grinder_Advanced/javacore.20190906.141110.29549.0829.txt
15:11:11 JVMDUMP013I Processed dump event "load", detail "java/util/Collections$EmptyIterator".
Source: https://ci.adoptopenjdk.net/view/Test_grinder/job/Grinder_Advanced/404/
There may be a fix for this actually. It would be worthwhile building with this PR https://github.com/eclipse/openj9/pull/3627 and then retesting.
That seems to have fixed it. There is now a NullPointerError
exception later in the code. The prefix that is attached is statically typed so it's possible the class name has changed in that time and the prefix is now incorrect. Will try running with contains()
instead to see if that helps the test find the class name.
Error Output:
11:28:48 --- Actual ---
11:28:48 java.base/java.lang.Thread.getStackTrace(Thread.java:1169)
11:28:48 DumpStackTest.consumeLambda(DumpStackTest.java:147)
11:28:48 DumpStackTest.lambda$testLambda$0(DumpStackTest.java:129)
11:28:48 DumpStackTest.testLambda(DumpStackTest.java:130)
11:28:48 DumpStackTest.main(DumpStackTest.java:45)
11:28:48 java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
11:28:48 java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
11:28:48 java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
11:28:48 java.base/java.lang.reflect.Method.invoke(Method.java:566)
11:28:48 com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
11:28:48 java.base/java.lang.Thread.run(Thread.java:831)
11:28:48 null
11:28:48 --- Expected ---
11:28:48 java.lang.Thread.getStackTrace(Thread.java)
11:28:48 DumpStackTest.consumeLambda(DumpStackTest.java)
11:28:48 DumpStackTest.lambda$testLambda$0(DumpStackTest.java)
11:28:48 DumpStackTest.testLambda(DumpStackTest.java)
11:28:48 DumpStackTest.main(DumpStackTest.java)
11:28:48 jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)
11:28:48 jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java)
11:28:48 jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java)
11:28:48 java.lang.reflect.Method.invoke(Method.java)
11:28:48 java.lang.Thread.run(Thread.java)
11:28:48 STDERR:
11:28:48 java.lang.NullPointerException
11:28:48 at DumpStackTest.assertStackTrace(DumpStackTest.java:217)
11:28:48 at DumpStackTest.consumeLambda(DumpStackTest.java:147)
11:28:48 at DumpStackTest.lambda$testLambda$0(DumpStackTest.java:129)
11:28:48 at DumpStackTest.testLambda(DumpStackTest.java:130)
11:28:48 at DumpStackTest.main(DumpStackTest.java:45)
11:28:48 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
11:28:48 at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
11:28:48 at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
11:28:48 at java.base/java.lang.reflect.Method.invoke(Method.java:566)
11:28:48 at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
11:28:48 at java.base/java.lang.Thread.run(Thread.java:831)
11:28:48 at null
11:28:48
11:28:48 JavaTest Message: Test threw exception: java.lang.NullPointerException
11:28:48 JavaTest Message: shutting down test
@DanHeidinga FYI, After working with the PR a bit today and modifying the test a little, inserting a try-catch for the NullPointerException at the place where it occurred, passes so this is the only issue with the test.
testLambda()
. This was the function that, prior to #3627, was failing with the RuntimeException
NEW STACK TRACE!! <- (Debug output)
--- Actual ---
java.base/java.lang.Thread.getStackTrace(Thread.java:1172)
DumpStackTest.consumeLambda(DumpStackTest.java:147)
DumpStackTest.lambda$testLambda$0(DumpStackTest.java:129)
DumpStackTest.testLambda(DumpStackTest.java:130)
DumpStackTest.main(DumpStackTest.java:45)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base/java.lang.reflect.Method.invoke(Method.java:566)
com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
java.base/java.lang.Thread.run(Thread.java:834)
null <- (Empty frame?)
--- Expected ---
java.lang.Thread.getStackTrace(Thread.java)
DumpStackTest.consumeLambda(DumpStackTest.java)
DumpStackTest.lambda$testLambda$0(DumpStackTest.java)
DumpStackTest.testLambda(DumpStackTest.java)
DumpStackTest.main(DumpStackTest.java)
jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java)
jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java)
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java)
java.lang.reflect.Method.invoke(Method.java)
java.lang.Thread.run(Thread.java)
NullPointerThrown! <- (NullPointerException caught)
NEW STACK TRACE!! --- Actual --- DumpStackTest.getStackTrace(DumpStackTest.java:101) DumpStackTest.consumeLambda(DumpStackTest.java:148) DumpStackTest.lambda$testLambda$0(DumpStackTest.java:129) DumpStackTest.testLambda(DumpStackTest.java:130) DumpStackTest.main(DumpStackTest.java:45) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.base/java.lang.reflect.Method.invoke(Method.java:566) com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) java.base/java.lang.Thread.run(Thread.java:834) null --- Expected --- DumpStackTest.getStackTrace(DumpStackTest.java) DumpStackTest.consumeLambda(DumpStackTest.java) DumpStackTest.lambda$testLambda$0(DumpStackTest.java) DumpStackTest.testLambda(DumpStackTest.java) DumpStackTest.main(DumpStackTest.java) jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java) jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java) jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java) java.lang.reflect.Method.invoke(Method.java) java.lang.Thread.run(Thread.java) NullPointerThrown! <- (Same issue as before)
- The J9 and Hotspot implementations of `Thread.java` appear identical so I believe this is just an output bug.
- The two streams (`Actual` and `Expected`) are also identical, other than the `null` frames, so the `NullPointerException` is caused by the stream's running out of objects to print
- From https://docs.oracle.com/javase/8/docs/api/java/util/Arrays.html and https://docs.oracle.com/javase/8/docs/api/java/util/stream/Stream.html
Throws: NullPointerException - if the result of the reduction is null
- A solution could be to add the try-catch in but I'm not sure if this would be accepted by the OpenJDK community (@smlambert Could something like this work? https://github.com/M-Davies/openj9-openjdk-jdk11/commit/2fa9485dbbe484a24aee8c8f347a2006857ee63f)
- Or, alternatively, figure out what this null frame is and go from there.
Update: The NullPointer exception I believe came from the frames which was hidden by previous impl for #3627, as it filters the frame that is written into the result array but have no control over the array size during creation leaving null elements trailing. The new impl for #3627 that have been merged avoids this issue by running the filter during swalk call which updates stackframe count.
in local testing, this test passed for JDK18 and JDKnext, will try with JDK11 & JDK17 to confirm if this is fixed by #3627 for all versions and re-enable the test
local testing passed for JDK 11 & JDK 17, opened PR to re-enable testing
Failure link
https://github.com/ibmruntimes/openj9-openjdk-jdk11/blob/openj9/test/jdk/java/lang/StackWalker/DumpStackTest.java
Consistent failure with jdk11-openj9 (all generic operating systems). Test passes on hotspot for all platforms
Java Version (when running locally)
Summary
The issue is a failed
assertEquals()
caused by an unexpected call frame in theconsumeLambda()
test.Failure output