search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.27k stars 721 forks source link

OpenJDK java/util/Map/InPlaceOpsCollisions NullPointerException String.charAt #17922

Open pshipton opened 1 year ago

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_aarch64_linux_Nightly_testList_1/26 jdk_util_0 java/util/Map/InPlaceOpsCollisions.java

21:58:49  test InPlaceOpsCollisions.testMergeNull("Hashtable with unique strings", MapWithCollisionsProviders$$Lambda$41/0x0000000000000000@ca803881, "Extra Value"): failure
21:58:49  java.lang.NullPointerException
21:58:49    at java.base/java.lang.String.charAt(String.java:1319)
21:58:49    at java.base/java.util.Formatter.checkText(Formatter.java:2730)
21:58:49    at java.base/java.util.Formatter.parse(Formatter.java:2708)
21:58:49    at java.base/java.util.Formatter.format(Formatter.java:2655)
21:58:49    at java.base/java.util.Formatter.format(Formatter.java:2609)
21:58:49    at java.base/java.lang.String.format(String.java:3728)
21:58:49    at InPlaceOpsCollisions.removeThirdKeys(InPlaceOpsCollisions.java:485)
21:58:49    at InPlaceOpsCollisions.testMergeNull(InPlaceOpsCollisions.java:426)
21:58:49    at jdk.internal.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
21:58:49    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
21:58:49    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
21:58:49    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
21:58:49    at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
21:58:49    at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
21:58:49    at org.testng.internal.MethodRunner.runInSequence(Met
21:58:49  
21:58:49  ...
21:58:49  Output overflow:
21:58:49  JT Harness has limited the test output to the text
21:58:49  at the beginning and the end, so that you can see how the
21:58:49  test began, and how it completed.
21:58:49  
21:58:49  If you need to see more of the output from the test,
21:58:49  set the system property javatest.maxOutputSize to a higher
21:58:49  value. The current value is 100000
21:58:49  ...
21:58:49  
21:58:49  l.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
21:58:49    at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
21:58:49    at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
21:58:49    at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
21:58:49    at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
21:58:49    at org.testng.TestRunner.privateRun(TestRunner.java:764)
21:58:49    at org.testng.TestRunner.run(TestRunner.java:585)
21:58:49    at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
21:58:49    at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
21:58:49    at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
21:58:49    at org.testng.SuiteRunner.run(SuiteRunner.java:286)
21:58:49    at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
21:58:49    at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
21:58:49    at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
21:58:49    at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
21:58:49    at org.testng.TestNG.runSuites(TestNG.java:1069)
21:58:49    at org.testng.TestNG.run(TestNG.java:1037)
21:58:49    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
21:58:49    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
21:58:49    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
21:58:49    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
21:58:49    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
21:58:49    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
21:58:49    at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
21:58:49    at java.base/java.lang.Thread.run(Thread.java:839)
21:58:49  test InPlaceOpsCollisions.testReplaceOldValue("TreeMap with colliding objects", MapWithCollisionsProviders$$Lambda$41/0x0000000000000000@e3f8f134, 2500): failure
21:58:49  java.lang.NullPointerException
21:58:49    at java.base/java.lang.String.charAt(String.java:1319)
21:58:49    at java.base/java.util.Formatter.checkText(Formatter.java:2730)
21:58:49    at java.base/java.util.Formatter.parse(Formatter.java:2708)
21:58:49    at java.base/java.util.Formatter.format(Formatter.java:2655)
21:58:49    at java.base/java.util.Formatter.format(Formatter.java:2609)
21:58:49    at java.base/java.lang.String.format(String.java:3728)
21:58:49    at InPlaceOpsCollisions.testReplaceOldValue(InPlaceOpsCollisions.java:122)
21:58:49    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
21:58:49    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
21:58:49    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
21:58:49    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
21:58:49    at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
21:58:49    at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
21:58:49    at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
21:58:49    at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
21:58:49    at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
21:58:49    at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
21:58:49    at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
21:58:49    at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
21:58:49    at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
21:58:49    at org.testng.TestRunner.privateRun(TestRunner.java:764)
21:58:49    at org.testng.TestRunner.run(TestRunner.java:585)
21:58:49    at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
21:58:49    at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
21:58:49    at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
21:58:49    at org.testng.SuiteRunner.run(SuiteRunner.java:286)
21:58:49    at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
21:58:49    at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
21:58:49    at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
21:58:49    at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
21:58:49    at org.testng.TestNG.runSuites(TestNG.java:1069)
21:58:49    at org.testng.TestNG.run(TestNG.java:1037)
21:58:49    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
21:58:49    at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
21:58:49    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
21:58:49    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
21:58:49    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
21:58:49    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
21:58:49    at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
21:58:49    at java.base/java.lang.Thread.run(Thread.java:839)

etc.
pshipton commented 1 year ago

Looks like a dup of https://github.com/eclipse-openj9/openj9/issues/17774

knn-k commented 1 year ago

Reproduced 3 times in a 30x Grinder job. https://openj9-jenkins.osuosl.org/job/Grinder_testList_0/253/consoleText

pshipton commented 1 year ago

3/30 is frequent enough to be a blocker.

knn-k commented 1 year ago

I haven't been able to reproduce the failure locally, running the test more than 60 times. I used the binary from https://openj9-jenkins.osuosl.org/job/Build_JDK11_aarch64_linux_Nightly/489/

knn-k commented 1 year ago

I ran a 30x Grinder job with the latest nightly build from https://openj9-jenkins.osuosl.org/job/Build_JDK11_aarch64_linux_Nightly/498/, and got no failures.

knn-k commented 1 year ago

Another 30x Grinder job was also successful. https://openj9-jenkins.osuosl.org/job/Grinder/2808/

hzongaro commented 1 year ago

Failure is highly intermittent, and hasn't been reproduced in a couple of weeks. I'll move it out to 0.43 for now.

pshipton commented 1 year ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_aarch64_linux_OpenJDK11_testList_1/7/ jdk_util_0 java/util/Map/InPlaceOpsCollisions.java

09:50:33  test InPlaceOpsCollisions.testReplaceOldValue("HashMap with unique strings", MapWithCollisionsProviders$$Lambda$41/0x0000000000000000@a1a85b9f, "Extra Value"): failure
09:50:33  java.lang.NullPointerException
09:50:33    at java.base/java.lang.String.charAt(String.java:1319)
09:50:33    at java.base/java.util.Formatter.checkText(Formatter.java:2730)
09:50:33    at java.base/java.util.Formatter.parse(Formatter.java:2708)
09:50:33    at java.base/java.util.Formatter.format(Formatter.java:2655)
09:50:33    at java.base/java.util.Formatter.format(Formatter.java:2609)
09:50:33    at java.base/java.lang.String.format(String.java:3728)
09:50:33    at InPlaceOpsCollisions.testReplaceOldValue(InPlaceOpsCollisions.java:122)

java/util/stream/boottest/java.base/java/util/stream/SpinedBufferTest.java

09:51:33  test java.util.stream.SpinedBufferTest.testSpliterator([I@c4fc7620, java.util.stream.SpinedBuffer@ec898b6b): failure
09:51:33  java.lang.NullPointerException
09:51:33    at java.base/java.lang.String.charAt(String.java:1319)
09:51:33    at java.base/java.util.Formatter.checkText(Formatter.java:2730)
09:51:33    at java.base/java.util.Formatter.parse(Formatter.java:2708)
09:51:33    at java.base/java.util.Formatter.format(Formatter.java:2655)
09:51:33    at java.base/java.util.Formatter.format(Formatter.java:2609)
09:51:33    at java.base/java.lang.String.format(String.java:3728)
09:51:33    at java.base/java.util.SpliteratorTestHelper.testSplitUntilNull(SpliteratorTestHelper.java:578)
09:51:33    at java.base/java.util.SpliteratorTestHelper.testSplitUntilNull(SpliteratorTestHelper.java:529)
09:51:33    at java.base/java.util.SpliteratorTestHelper.testSpliterator(SpliteratorTestHelper.java:167)
09:51:33    at java.base/java.util.SpliteratorTestHelper.testSpliterator(SpliteratorTestHelper.java:53)
09:51:33    at java.base/java.util.SpliteratorTestHelper.testSpliterator(SpliteratorTestHelper.java:48)
09:51:33    at java.base/java.util.stream.SpinedBufferTest.testSpliterator(SpinedBufferTest.java:92)
knn-k commented 1 year ago

I ran a 20x jdk_util_0 Grinder job, and got no failures. https://openj9-jenkins.osuosl.org/job/Grinder/2875/

knn-k commented 12 months ago

Another 20x Grinder job did not fail, either. https://openj9-jenkins.osuosl.org/job/Grinder/2876/

Akira1Saitoh commented 11 months ago

I was able to reproduce it and get dumps with -Xdump option.

https://hyc-runtimes-jenkins.swg-devops.com/job/Grinder/35030/

[2023-09-18T09:54:25.354Z] STDERR:
[2023-09-18T09:54:25.354Z] JVMDUMP039I Processing dump event "systhrow", detail "java/lang/NullPointerException" at 2023/09/18 05:26:33 - please wait.
[2023-09-18T09:54:25.354Z] JVMDUMP032I JVM requested System dump using '/home/jenkins/workspace/Grinder/aqa-tests/TKG/output_16950234906686/jdk_custom_0_ITER_69/work/scratch/0/core.20230918.052633.2686893.0001.dmp' in response to an event
[2023-09-18T09:54:25.354Z] JVMDUMP010I System dump written to /home/jenkins/workspace/Grinder/aqa-tests/TKG/output_16950234906686/jdk_custom_0_ITER_69/work/scratch/0/core.20230918.052633.2686893.0001.dmp
[2023-09-18T09:54:25.354Z] JVMDUMP032I JVM requested Java dump using '/home/jenkins/workspace/Grinder/aqa-tests/TKG/output_16950234906686/jdk_custom_0_ITER_69/work/scratch/0/javacore.20230918.052633.2686893.0002.txt' in response to an event
[2023-09-18T09:54:25.354Z] JVMDUMP010I Java dump written to /home/jenkins/workspace/Grinder/aqa-tests/TKG/output_16950234906686/jdk_custom_0_ITER_69/work/scratch/0/javacore.20230918.052633.2686893.0002.txt
[2023-09-18T09:54:25.354Z] JVMDUMP032I JVM requested JIT dump using '/home/jenkins/workspace/Grinder/aqa-tests/TKG/output_16950234906686/jdk_custom_0_ITER_69/work/scratch/0/jitdump.20230918.052633.2686893.0003.dmp' in response to an event
[2023-09-18T09:54:25.354Z] JVMDUMP051I JIT dump occurred in 'MainThread' thread 0x00000000001B1400
[2023-09-18T09:54:25.354Z] JVMDUMP053I JIT dump is recompiling java/util/Formatter.format(Ljava/util/Locale;Ljava/lang/String;[Ljava/lang/Object;)Ljava/util/Formatter;

Unfortunately, jitdump was not available.

1XMCURTHDINFO  Current thread
3XMTHREADINFO      "MainThread" J9VMThread:0x00000000001B1400, omrthread_t:0x0000FFFF7828CA40, java/lang/Thread:0x00000000E00CD2C0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1A, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000000E0044E60)
3XMTHREADINFO1            (native thread ID:0x28FFCA, native priority:0x5, native policy:UNKNOWN, vmstate:R, vm thread flags:0x00041020)
3XMTHREADINFO2            (native stack address range from:0x0000FFFF5D4D4000, to:0x0000FFFF5D514000, size:0x40000)
3XMCPUTIME               CPU usage total: 34.072865580 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/String.charAt(String.java:1319(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.checkText(Formatter.java:2730(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.parse(Formatter.java:2708(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2655(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2609(Compiled Code))
4XESTACKTRACE                at java/lang/String.format(String.java:3728(Compiled Code))
4XESTACKTRACE                at InPlaceOpsCollisions.testMergeNull(InPlaceOpsCollisions.java:446(Compiled Code))
...
<1b1400> *** BEGIN STACK WALK, flags = 00400001 walkThread = 0x00000000001B1400 ***
<1b1400>        ITERATE_O_SLOTS
<1b1400>        RECORD_BYTECODE_PC_OFFSET
<1b1400> Initial values: walkSP = 0x00000000001B6B08, PC = 0x0000000000000005, literals = 0x0000000000000000, A0 = 0x00000000001
B6B28, j2iFrame = 0x0000000000000000, ELS = 0x0000FFFF5D511B80, decomp = 0x0000000000000000
<1b1400> JIT resolve frame: bp = 0x00000000001B6B28, sp = 0x00000000001B6B08, pc = 0x0000000000000005, cp = 0x0000000000000000, 
arg0EA = 0x00000000001B6B28, flags = 0x0000000000080000
<1b1400>        Object push (savedJITException)
<1b1400>                O-Slot[0x00000000001B6B08] = 0x0000000000000000
<1b1400>        Generic resolve
<1b1400>        unwindSP initialized to 0x00000000001B6B30
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511810] = UDATA(0x0000000000000000) (jit_r0)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511818] = UDATA(0x000000000000001E) (jit_r1)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511820] = UDATA(0x00000000FFDA5818) (jit_r2)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511828] = UDATA(0x00000000E0572C60) (jit_r3)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511830] = UDATA(0x000000000000001E) (jit_r4)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511838] = UDATA(0x00000000FFDA5758) (jit_r5)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511840] = UDATA(0x00000000E0149558) (jit_r6)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511848] = UDATA(0x00000000E0572C60) (jit_r7)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511850] = UDATA(0x00000000FFDA57C0) (jit_r8)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511858] = UDATA(0x00000000E003F020) (jit_r9)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511860] = UDATA(0x0000000000000017) (jit_r10)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511868] = UDATA(0x00000000E0572C70) (jit_r11)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511870] = UDATA(0x0000000000000000) (jit_r12)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511878] = UDATA(0x000000000000001E) (jit_r13)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511880] = UDATA(0x0000000000000000) (jit_r14)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511888] = UDATA(0x0000000000000001) (jit_r15)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511890] = UDATA(0x0000FFFF7DC7D984) (jit_r16)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511898] = UDATA(0x0000FFFF7F7A64C0) (jit_r17)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118A0] = UDATA(0x000000000000001C) (jit_r18)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118A8] = UDATA(0x00000000001B1400) (jit_r19)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118B0] = UDATA(0x00000000001B6B30) (jit_r20)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118B8] = UDATA(0x00000000FFDA5770) (jit_r21)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118C0] = UDATA(0x00000000E01713F8) (jit_r22)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118C8] = UDATA(0x0000000000000000) (jit_r23)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118D0] = UDATA(0x000000000000001E) (jit_r24)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118D8] = UDATA(0x00000000FFDA5758) (jit_r25)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118E0] = UDATA(0x00000000E0149558) (jit_r26)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118E8] = UDATA(0x0000000000000001) (jit_r27)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118F0] = UDATA(0x0000000000000017) (jit_r28)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D5118F8] = UDATA(0x0000002B5D511A68) (jit_r29)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511900] = UDATA(0x0000FFFF5FBC6138) (jit_r30)
<1b1400>        JIT-Resolve-RegisterMap[0x0000FFFF5D511908] = UDATA(0x0000FFFF7802EA90) (jit_r31)
<1b1400> JIT inline frame: bp = 0x00000000001B6D48, pc = 0x0000FFFF5FBC8171, unwindSP = 0x00000000001B6B30, cp = 0x0000000000034
A20, arg0EA = 0x0000000000000000, jitInfo = 0x0000FFFF5C0D5698
<1b1400>        Method: java/lang/String.charAt(I)C !j9method 0x0000000000033D38
<1b1400>        Bytecode index = 2, inlineDepth = 3, PC offset = 0x000000000010C355
<1b1400> JIT inline frame: bp = 0x00000000001B6D48, pc = 0x0000FFFF5FBC8171, unwindSP = 0x00000000001B6B30, cp = 0x00000000001F8
8F0, arg0EA = 0x0000000000000000, jitInfo = 0x0000FFFF5C0D5698
<1b1400>        Method: java/util/Formatter.checkText(Ljava/lang/String;II)V !j9method 0x00000000001F9338
<1b1400>        Bytecode index = 9, inlineDepth = 2, PC offset = 0x0000000000129031
<1b1400> JIT inline frame: bp = 0x00000000001B6D48, pc = 0x0000FFFF5FBC8171, unwindSP = 0x00000000001B6B30, cp = 0x00000000001F8
8F0, arg0EA = 0x0000000000000000, jitInfo = 0x0000FFFF5C0D5698
<1b1400>        Method: java/util/Formatter.parse(Ljava/lang/String;)Ljava/util/List; !j9method 0x00000000001F9318
<1b1400>        Bytecode index = 57, inlineDepth = 1, PC offset = 0x000000000004817D
<1b1400> JIT frame: bp = 0x00000000001B6D48, pc = 0x0000FFFF5FBC8171, unwindSP = 0x00000000001B6B30, cp = 0x00000000001F88F0, ar
g0EA = 0x00000000001B6D68, jitInfo = 0x0000FFFF5C0D5698
<1b1400>        Method: java/util/Formatter.format(Ljava/util/Locale;Ljava/lang/String;[Ljava/lang/Object;)Ljava/util/Formatter;
 !j9method 0x00000000001F92F8
<1b1400>        Bytecode index = 57, inlineDepth = 0, PC offset = 0x0000000000003925
<1b1400>        stackMap=0x0000FFFF5C0D7D41, slots=I16(0x0004) parmBaseOffset=I16(0x0008), parmSlots=U16(0x0004), localBaseOffse
t=I16(0xFE90)
<1b1400>        Described JIT args starting at 0x00000000001B6D50 for U16(0x0004) slots
<1b1400>                O-Slot: : a3[0x00000000001B6D50] = 0x00000000FFDA56F0
<1b1400>                O-Slot: : a2[0x00000000001B6D58] = 0x00000000E0572C60
<1b1400>                O-Slot: : a1[0x00000000001B6D60] = 0x00000000E0038A90
<1b1400>                O-Slot: : a0[0x00000000001B6D68] = 0x00000000FFDA5710
<1b1400>        Described JIT temps starting at 0x00000000001B6BD8 for IDATA(0x000000000000002E) slots
...
(kca) x/64i 0xffff5fbc810c
0xffff5fbc810c {java/util/Formatter.format} +14528                      d2867300 mov       x0, #0x3398 CONST 0x33398 Ptr Obj - {java/lang/String$StringCompressionFlag}T <<< +4232
0xffff5fbc8110 {java/util/Formatter.format} +14532                      f2a00060 movk      x0, #3, lsl #16
0xffff5fbc8114 {java/util/Formatter.format} +14536                      f9400000 ldr       x0, [x0]
0xffff5fbc8118 {java/util/Formatter.format} +14540                      f9411680 ldr       x0, [x20, #0x228]      <--- String "compute: containsValue(%s[%s])"
0xffff5fbc811c {java/util/Formatter.format} +14544                      b940040b ldr       w11, [x0, #4]            <--- [B value
0xffff5fbc8120 {java/util/Formatter.format} +14548                      b940080c ldr       w12, [x0, #8]           <--- B coder
0xffff5fbc8124 {java/util/Formatter.format} +14552                      b9400560 ldr       w0, [x11, #4]
0xffff5fbc8128 {java/util/Formatter.format} +14556                      1acc240d lsr       w13, w0, w12
0xffff5fbc812c {java/util/Formatter.format} +14560                      d2867300 mov       x0, #0x3398 CONST 0x33398 Ptr Obj - {java/lang/String$StringCompressionFlag}T
0xffff5fbc8130 {java/util/Formatter.format} +14564                      f2a00060 movk      x0, #3, lsl #16
0xffff5fbc8134 {java/util/Formatter.format} +14568                      f9400009 ldr       x9, [x0]
0xffff5fbc8138 {java/util/Formatter.format} +14572                      f9402a60 ldr       x0, [x19, #0x50] <<< ^+17636
0xffff5fbc813c {java/util/Formatter.format} +14576                      b100041f cmn       x0, #1
0xffff5fbc8140 {java/util/Formatter.format} +14580         32:2         54031ec0 b.eq      #0xffff5fbce518 C>> +40140  // ificmpgt C>> +63
0xffff5fbc8144 {java/util/Formatter.format} +14584                      6b0d01df cmp       w14, w13 <<< ^+40144
0xffff5fbc8148 {java/util/Formatter.format} +14588                      540280ea b.ge      #0xffff5fbcd164 C>> +35096 
0xffff5fbc814c {java/util/Formatter.format} +14592                      d503201f nop       
0xffff5fbc8150 {java/util/Formatter.format} +14596                      b9400560 ldr       w0, [x11, #4]
0xffff5fbc8154 {java/util/Formatter.format} +14600                      1acc2401 lsr       w1, w0, w12
0xffff5fbc8158 {java/util/Formatter.format} +14604                      4b0e0021 sub       w1, w1, w14
0xffff5fbc815c {java/util/Formatter.format} +14608                      528b75c0 mov       w0, #0x5bae
0xffff5fbc8160 {java/util/Formatter.format} +14612                      72a008a0 movk      w0, #0x45, lsl #16
0xffff5fbc8164 {java/util/Formatter.format} +14616                      6b00003f cmp       w1, w0
0xffff5fbc8168 {java/util/Formatter.format} +14620                      5400ec2c b.gt      #0xffff5fbc9eec C>> +22176 
0xffff5fbc816c {java/util/Formatter.format} +14624                      f9405680 ldr       x0, [x20, #0xa8]   <--- 0 is loaded into x0
0xffff5fbc8170 {java/util/Formatter.format} +14628                      b9400401 ldr       w1, [x0, #4]          <--- NPE here
0xffff5fbc8174 {java/util/Formatter.format} +14632                      b9409280 ldr       w0, [x20, #0x90]
0xffff5fbc8178 {java/util/Formatter.format} +14636                      1ac02422 lsr       w2, w1, w0
0xffff5fbc817c {java/util/Formatter.format} +14640                      b401ad09 cbz       x9, #0xffff5fbcb71c C>> +28368 
0xffff5fbc8180 {java/util/Formatter.format} +14644                      b900928c str       w12, [x20, #0x90]
0xffff5fbc8184 {java/util/Formatter.format} +14648                      b9409280 ldr       w0, [x20, #0x90]
0xffff5fbc8188 {java/util/Formatter.format} +14652                      35005c00 cbnz      w0, #0xffff5fbc8d08 C>> +17596 
0xffff5fbc818c {java/util/Formatter.format} +14656                      b9409280 ldr       w0, [x20, #0x90]
0xffff5fbc8190 {java/util/Formatter.format} +14660                      34005de0 cbz       w0, #0xffff5fbc8d4c C>> +17664 
0xffff5fbc8194 {java/util/Formatter.format} +14664                      f900568b str       x11, [x20, #0xa8]
0xffff5fbc8198 {java/util/Formatter.format} +14668                      f9405680 ldr       x0, [x20, #0xa8]
0xffff5fbc819c {java/util/Formatter.format} +14672                      8b2ec000 add       x0, x0, w14, sxtw
0xffff5fbc81a0 {java/util/Formatter.format} +14676                      39402000 ldrb      w0, [x0, #8]
0xffff5fbc81a4 {java/util/Formatter.format} +14680                      7100941f cmp       w0, #0x25
0xffff5fbc81a8 {java/util/Formatter.format} +14684                      54014040 b.eq      #0xffff5fbca9b0 C>> +24932
Akira1Saitoh commented 11 months ago

I got a jitdump generated on NullPointerException. https://hyc-runtimes-jenkins.swg-devops.com/job/Grinder_iteration_2/2478/

NullPointerException was thrown when loading arrayLength of String.value because the address loaded from [w20, 168] <temp slot 68> was 0.

29373  \\ java/util/Formatter.format(Ljava/util/Locale;Ljava/lang/String;[Ljava/lang/Object;)Ljava/util/Formatter;
2929374  \\   12 JBinvokespecial 55 java/util/Formatter.parse(Ljava/lang/String;)Ljava/util/List;
2929375  \\      57 JBinvokestatic 72 java/util/Formatter.checkText(Ljava/lang/String;II)V
2929376  \\          9 JBinvokevirtual 79 java/lang/String.charAt(I)C
2929377  \\             7 JBinvokevirtual 32 java/lang/String.lengthInternal()I
2929378  \\                7 JBgetfield 34 java/lang/String.value [B
2929379 
2929380     0xffff6633cf84 000038f0 [    0xfffee381ab00] f9405680 7     ldrimmx         w0, [w20, 168]          # SymRef  <temp slot 68>[#3577  Auto +168] [flags 0x7 0x0 ]     
2929381 
2929382  \\ java/util/Formatter.format(Ljava/util/Locale;Ljava/lang/String;[Ljava/lang/Object;)Ljava/util/Formatter;
2929383  \\   12 JBinvokespecial 55 java/util/Formatter.parse(Ljava/lang/String;)Ljava/util/List;
2929384  \\      57 JBinvokestatic 72 java/util/Formatter.checkText(Ljava/lang/String;II)V
2929385  \\          9 JBinvokevirtual 79 java/lang/String.charAt(I)C
2929386  \\             7 JBinvokevirtual 32 java/lang/String.lengthInternal()I
2929387  \\               10 JBarraylength 
2929388 
2929389     0xffff6633cf88 000038f4 [    0xfffee381ab90] b9400401 10    ldrimmw         w1, [w0, 4]             # SymRef  <contiguous-array-size>[#261  Shadow +4] [flags 0x603 0x0 ]      <-- NPE here

The aload node for <temp slot 68> is n35809n. I do not find a astore node for <temp slot 68> before this node, although there are many after it.

2718809  n35813n  (  0)  treetop                                                                              [    0xfffeedd8aa0
2718809 0] bci=[33,15,2288] rc=0 vc=4032 vn=- li=1706 udi=- nc=1
2718810  n35812n  (  0)    iushr (in GPR_    0xfffee381ad70) (X>=0 cannotOverflow )                           [    0xfffeedd8a9b
2718810 0] bci=[33,15,2288] rc=0 vc=4032 vn=- li=1706 udi=44400 nc=2 flg=0x1100
2718811  n35810n  (  0)      iloadi  <contiguous-array-size>[#261  Shadow +4] [flags 0x603 0x0 ] (in GPR_    0xfffee381a980) (X>
2718811 =0 cannotOverflow )  [    0xfffeedd8a910] bci=[33,10,2288] rc=0 vc=4032 vn=- li=1706 udi=43392 nc=1 flg=0x1100
2718812  n35809n  (  0)        aload  <temp slot 68>[#3577  Auto] [flags 0x7 0x0 ] (in &GPR_    0xfffee381aa40) (X!=0 )  [    0x
2718812 fffeedd8a8c0] bci=[33,7,2288] rc=0 vc=4032 vn=- li=1706 udi=43584 nc=0 flg=0x4
2718813  n35811n  (  0)      iload  <temp slot 69>[#3578  Auto] [flags 0x3 0x0 ] (in GPR_    0xfffee381ac20) (cannotOverflow )  
2718813 [    0xfffeedd8a960] bci=[33,12,2288] rc=0 vc=4032 vn=- li=1706 udi=44064 nc=0 flg=0x1000
2718814 ------------------------------
2718815 
2718816  [    0xfffee381ab00]   7       ldrimmx         &GPR_    0xfffee381aa40, [w20, 0]               # SymRef  <temp slot 68>
2718816 [#3577  Auto] [flags 0x7 0x0 ]  
2718817  [    0xfffee381ab90]   10      ldrimmw         GPR_    0xfffee381a980, [&GPR_    0xfffee381aa40, 4]            # SymRef
2718817   <contiguous-array-size>[#261  Shadow +4] [flags 0x603 0x0 ]   
2718818  [    0xfffee381ace0]   12      ldrimmw         GPR_    0xfffee381ac20, [w20, 0]                # SymRef  <temp slot 69>
2718818 [#3578  Auto] [flags 0x3 0x0 ]  
2718819  [    0xfffee381ade0]   15      lsrvw   GPR_    0xfffee381ad70, GPR_    0xfffee381a980, GPR_    0xfffee381ac20

In the optimization phase, there was an astore node for <temp slot 68> (n35794n) before n35809n, but it was moved to block_2099 by generalStoreSinking.

1904811 n35838n   BBStart <block_1701> (freq 509) (extension of previous block) (cold) (in loop 378)  [    0xfffeedd8b1d0] bci=[32,2,1319] rc=0 vc=12763 vn=- li=- udi=- nc=0
1904812 n35794n   astore  <temp slot 68>[#3577  Auto] [flags 0x7 0x0 ] (X!=0 )                        [    0xfffeedd8a410] bci=[33,7,2288] rc=0 vc=12763 vn=- li=- udi=417 nc=1 flg=0x4
1904813 n35793n     aload  <temp slot 90>[#3604  Auto] [flags 0x7 0x0 ] (X!=0 createdByPRE )          [    0xfffeedd8a3c0] bci=[33,7,2288] rc=2 vc=12763 vn=- li=- udi=611 nc=0 flg=0x40004
1904814 n35800n   istore  <temp slot 69>[#3578  Auto] [flags 0x3 0x0 ]                                [    0xfffeedd8a5f0] bci=[33,12,2288] rc=0 vc=12763 vn=- li=- udi=418 nc=1
1904815 n35799n     iload  <temp slot 92>[#3606  Auto] [flags 0x3 0x0 ] (cannotOverflow createdByPRE )  [    0xfffeedd8a5a0] bci=[33,12,2288] rc=2 vc=12763 vn=- li=- udi=612 nc=0 flg=0x41000
1904816 n35808n   ificmpgt --> block_1696 BBStart at n35756n (maxLoopIternGuard )                     [    0xfffeedd8a870] bci=[33,15,2288] rc=0 vc=12763 vn=- li=- udi=- nc=2 flg=0x820
1904817 n35806n     isub (cannotOverflow )                                                            [    0xfffeedd8a7d0] bci=[33,15,2288] rc=1 vc=12763 vn=- li=- udi=- nc=2 flg=0x1000
1904818 n35804n       iushr (X>=0 cannotOverflow )                                                    [    0xfffeedd8a730] bci=[33,15,2288] rc=1 vc=12763 vn=- li=- udi=- nc=2 flg=0x1100
1904819 n35802n         arraylength (stride 1) (X>=0 cannotOverflow )                                 [    0xfffeedd8a690] bci=[33,10,2288] rc=1 vc=12763 vn=- li=- udi=- nc=1 flg=0x1100
1904820 n35793n           ==>aload
1904821 n35799n         ==>iload
1904822 n35805n       iload  i<auto slot 3>[#2343  Auto] [flags 0x3 0x0 ] (X>=0 cannotOverflow )      [    0xfffeedd8a780] bci=[32,5,1319] rc=1 vc=12763 vn=- li=- udi=613 nc=0 flg=0x1100
1904823 n35807n     iconst 0x455bae (X!=0 X>=0 )                                                      [    0xfffeedd8a820] bci=[33,15,2288] rc=1 vc=12763 vn=- li=- udi=- nc=0 flg=0x104
1904824 n35828n   BBEnd </block_1701> (cold)                                                          [    0xfffeedd8aeb0] bci=[32,2,1319] rc=0 vc=12763 vn=- li=- udi=- nc=0
1904825 n35825n   BBStart <block_1706> (freq 509) (extension of previous block) (cold) (in loop 378)  [    0xfffeedd8adc0] bci=[32,2,1319] rc=0 vc=12763 vn=- li=- udi=- nc=0
1904826 n35813n   istore  <temp slot 70>[#3579  Auto] [flags 0x3 0x0 ]                                [    0xfffeedd8aa00] bci=[33,15,2288] rc=0 vc=12763 vn=- li=- udi=419 nc=1
1904827 n35812n     iushr (X>=0 cannotOverflow )                                                      [    0xfffeedd8a9b0] bci=[33,15,2288] rc=1 vc=12763 vn=- li=- udi=- nc=2 flg=0x1100
1904828 n35810n       arraylength (stride 1) (X>=0 cannotOverflow )                                   [    0xfffeedd8a910] bci=[33,10,2288] rc=1 vc=12763 vn=- li=- udi=- nc=1 flg=0x1100
1904829 n35809n         aload  <temp slot 68>[#3577  Auto] [flags 0x7 0x0 ] (X!=0 )                   [    0xfffeedd8a8c0] bci=[33,7,2288] rc=1 vc=12763 vn=- li=- udi=614 nc=0 flg=0x4
1904830 n35811n       iload  <temp slot 69>[#3578  Auto] [flags 0x3 0x0 ] (cannotOverflow )           [    0xfffeedd8a960] bci=[33,12,2288] rc=1 vc=12763 vn=- li=- udi=615 nc=0 flg=0x1000
1904831 n45386n   ifacmpeq --> block_2055 BBStart at n45378n (swappedChildren )                       [    0xfffeea525a50] bci=[32,23,1321] rc=0 vc=12763 vn=- li=- udi=- nc=2 flg=0x20020
1904832 n45384n     aload  <temp slot 118>[#3632  Auto] [flags 0x7 0x0 ] (createdByPRE )              [    0xfffeea5259b0] bci=[32,20,1321] rc=1 vc=12763 vn=- li=- udi=- nc=0 flg=0x40000
1904833 n45385n     aconst NULL (X==0 )                                                               [    0xfffeea525a00] bci=[32,19,1321] rc=1 vc=12763 vn=- li=- udi=- nc=0 flg=0x2
1904834 n45394n   BBEnd </block_1706> (cold) 
...
1904849 n45897n   BBStart <block_2099> (freq 509) (extension of previous block) (cold) (in loop 378)  [    0xfffeea52fa00] bci=[1904849 31,9,2730] rc=0 vc=12763 vn=- li=- udi=- nc=0
1904850 n45899n   istore  <temp slot 6>[#2376  Auto] [flags 0x3 0x0 ]                                 [    0xfffeea52faa0] bci=[1904850 32,50,1322] rc=0 vc=12763 vn=- li=- udi=420 nc=1
1918338 <optimization id=217 name=generalStoreSinking method=java/util/Formatter.format(Ljava/util/Locale;Ljava/lang/String;[Ljava/lang/Object;)Ljava/util/Formatter;>
1918339 Performing 217: generalStoreSinking
...
1918390 [ 16104] O^O SINK STORES:  Finding placements for store [0000FFFEEDD8A410]  with tree depth 2
...
1923744 n35838n   BBStart <block_1701> (freq 509) (extension of previous block) (cold)                [    0xfffeedd8b1d0] bci=[
1923744 32,2,1319] rc=0 vc=3 vn=- li=- udi=- nc=0
1923745 n35808n   ificmpgt --> block_1696 BBStart at n35756n (maxLoopIternGuard )                     [    0xfffeedd8a870] bci=[33,15,2288] rc=0 vc=1707 vn=- li=- udi=- nc=2 flg=0x820
1923746 n35806n     isub (cannotOverflow )                                                            [    0xfffeedd8a7d0] bci=[33,15,2288] rc=1 vc=1707 vn=- li=- udi=- nc=2 flg=0x1000
1923747 n35804n       iushr (X>=0 cannotOverflow )                                                    [    0xfffeedd8a730] bci=[33,15,2288] rc=1 vc=1707 vn=- li=- udi=- nc=2 flg=0x1100
1923748 n35802n         arraylength (stride 1) (X>=0 cannotOverflow )                                 [    0xfffeedd8a690] bci=[33,10,2288] rc=1 vc=1707 vn=- li=- udi=- nc=1 flg=0x1100
1923749 n35793n           aload  <temp slot 90>[#3604  Auto] [flags 0x7 0x0 ] (X!=0 createdByPRE )    [    0xfffeedd8a3c0] bci=[33,7,2288] rc=2 vc=1709 vn=- li=- udi=611 nc=0 flg=0x40004
1923750 n35799n         iload  <temp slot 92>[#3606  Auto] [flags 0x3 0x0 ] (cannotOverflow createdByPRE )  [    0xfffeedd8a5a0]  bci=[33,12,2288] rc=2 vc=1708 vn=- li=- udi=612 nc=0 flg=0x41000
1923751 n35805n       iload  i<auto slot 3>[#2343  Auto] [flags 0x3 0x0 ] (X>=0 cannotOverflow )      [    0xfffeedd8a780] bci=[32,5,1319] rc=1 vc=1707 vn=- li=- udi=613 nc=0 flg=0x1100
1923752 n35807n     iconst 0x455bae (X!=0 X>=0 )                                                      [    0xfffeedd8a820] bci=[33,15,2288] rc=1 vc=1707 vn=- li=- udi=- nc=0 flg=0x104
1923753 n35828n   BBEnd </block_1701> (cold)                                                          [    0xfffeedd8aeb0] bci=[32,2,1319] rc=0 vc=3 vn=- li=- udi=- nc=0
1923754 n35825n   BBStart <block_1706> (freq 509) (extension of previous block) (cold)                [    0xfffeedd8adc0] bci=[32,2,1319] rc=0 vc=3 vn=- li=- udi=- nc=0
1923755 n35813n   treetop                                                                             [    0xfffeedd8aa00] bci=[33,15,2288] rc=0 vc=1706 vn=- li=- udi=419 nc=1
1923756 n35812n     iushr (X>=0 cannotOverflow )                                                      [    0xfffeedd8a9b0] bci=[33,15,2288] rc=1 vc=1706 vn=- li=- udi=- nc=2 flg=0x1100
1923757 n35810n       arraylength (stride 1) (X>=0 cannotOverflow )                                   [    0xfffeedd8a910] bci=[33,10,2288] rc=1 vc=1706 vn=- li=- udi=- nc=1 flg=0x1100
1923758 n35809n         aload  <temp slot 68>[#3577  Auto] [flags 0x7 0x0 ] (X!=0 )                   [    0xfffeedd8a8c0] bci=[33,7,2288] rc=1 vc=1706 vn=- li=- udi=614 nc=0 flg=0x4
...
1923782 n45897n   BBStart <block_2099> (freq 509) (extension of previous block) (cold)                [    0xfffeea52fa00] bci=[31,9,2730] rc=0 vc=3 vn=- li=- udi=- nc=0
1923783 n35794n   astore  <temp slot 68>[#3577  Auto] [flags 0x7 0x0 ] (X!=0 )                        [    0xfffeedd8a410] bci=[1923783 33,7,2288] rc=0 vc=1709 vn=- li=- udi=417 nc=1 flg=0x4
1923784 n35793n     ==>aload
1923785 n45899n   istore  <temp slot 6>[#2376  Auto] [flags 0x3 0x0 ]                                 [    0xfffeea52faa0] bci=[1923785 32,50,1322] rc=0 vc=1700 vn=- li=- udi=420 nc=1
knn-k commented 11 months ago

@hzongaro Please take a look at @Akira1Saitoh's comment above. It looks like an issue in optimization.

hzongaro commented 11 months ago

@hzongaro Please take a look at @Akira1Saitoh's comment above. It looks like an issue in optimization.

Thank you for the investigation, @Akira1Saitoh and @knn-k - I will take a look.

hzongaro commented 11 months ago

@jmesyou, may I ask you to take a look at this problem? I've been trying to reproduce the failure in Grinder runs with extra tracing of General Store Sinking in the jitdump, using the following EXTRA_OPTION, but haven't succeeded.

"-Xdump:jit:events=throw+systhrow,filter=java/lang/NullPointerException,request=serial,opts=traceGeneralStoreSinking"

However, there's an internal grinder run that's currently in progress that has shown at least one NullPointerException in String.charAt. We'll see whether it has a useful jitdump.

hzongaro commented 11 months ago

FYI - on any future Grinder reruns, you might want to used the range suboption to reduce the number of jitdumps produced:

-Xdump:jit:events=throw+systhrow,filter=java/lang/NullPointerException,range=1..3,request=serial,opts=traceGeneralStoreSinking
hzongaro commented 11 months ago

It seems that I was mistaken about the usage of the opts suboption of -Xdump for jitdumps. An example from a jitdump-related issue #9479 hinted that compiler trace options would be permitted as values for the opts suboption:

-Xdump:jit:
    events=gpf+abort,
    label=/home/user/jitdump.%Y%m%d.%H%M%S.%pid.%seq.dmp,
    range=1..0,
    priority=200,
    request=serial,
    opts=traceOSR+traceLiveness+traceAliases

However, when support for the opts suboption was actually added for jitdumps in pull request #11989, it was used to specify the name of a method that should be queued for recompilation with tracing.

-Xdump:jit:
    events=throw,
    filter=*NullPointerException#java/util/Calendar.setTime,
    range=1..1,
    opts=java/lang/String.indexOf(II)I

Thus, my use of opts=traceGeneralStoreSinking did not have the desired effect of tracing store sinking in the jitdump recompilation. :-(

pshipton commented 11 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_aarch64_linux_OMR_testList_2/33/ java/util/stream/boottest/java.base/java/util/stream/SpinedBufferTest.java

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_aarch64_linux_OMR_testList_1/34/ java/util/Map/InPlaceOpsCollisions.java

hzongaro commented 10 months ago

Moving to the backlog for now, as it's a rather intermittent failure. @jmesyou will continue investigating.

pshipton commented 9 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_aarch64_linux_Release_testList_1/17/

pshipton commented 8 months ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.openjdk_aarch64_mac_OMR_testList_0/37

cjjdespres commented 2 months ago

Something similar to this (failures in InPlaceOpsCollisions and SpinedBufferTest) seems to have started happening in the JITServer nightly tests as well, e.g. in https://hyc-runtimes-jenkins.swg-devops.com/job/Test_openjdk11_j9_sanity.openjdk_s390x_linux_jit_Personal_testList_1/335/

[2024-06-10T08:43:40.914Z] test InPlaceOpsCollisions.testReplaceOldValue("WeakHashMap with colliding objects", MapWithCollisionsProviders$$Lambda$41/0x0000000000000000@e428cf26, 2500): failure
[2024-06-10T08:43:40.914Z] java.lang.NullPointerException
[2024-06-10T08:43:40.914Z]  at java.base/java.util.Formatter$FormatSpecifier.precision(Formatter.java:2829)
[2024-06-10T08:43:40.914Z]  at java.base/java.util.Formatter$FormatSpecifier.<init>(Formatter.java:2856)
[2024-06-10T08:43:40.914Z]  at java.base/java.util.Formatter.parse(Formatter.java:2713)
[2024-06-10T08:43:40.915Z]  at java.base/java.util.Formatter.format(Formatter.java:2655)
[2024-06-10T08:43:40.915Z]  at java.base/java.util.Formatter.format(Formatter.java:2609)
[2024-06-10T08:43:40.915Z]  at java.base/java.lang.String.format(String.java:3741)
[2024-06-10T08:43:40.915Z]  at InPlaceOpsCollisions.testReplaceOldValue(InPlaceOpsCollisions.java:122)

[2024-06-10T08:45:47.045Z] java.lang.NullPointerException
[2024-06-10T08:45:47.045Z]  at java.base/java.util.Formatter$FormatSpecifier.precision(Formatter.java:2829)
[2024-06-10T08:45:47.045Z]  at java.base/java.util.Formatter$FormatSpecifier.<init>(Formatter.java:2856)
[2024-06-10T08:45:47.045Z]  at java.base/java.util.Formatter.parse(Formatter.java:2713)
[2024-06-10T08:45:47.045Z]  at java.base/java.util.Formatter.format(Formatter.java:2655)
[2024-06-10T08:45:47.045Z]  at java.base/java.util.Formatter.format(Formatter.java:2609)
[2024-06-10T08:45:47.045Z]  at java.base/java.lang.String.format(String.java:3741)
[2024-06-10T08:45:47.045Z]  at java.base/java.util.SpliteratorTestHelper.testSplitUntilNull(SpliteratorTestHelper.java:578)

though it's a different platform.

hzongaro commented 2 months ago

The IL that results after General Store Sinking that @Akira1Saitoh described above looks very similar to the IL in https://github.com/eclipse-openj9/openj9/issues/17515#issuecomment-2182890501. These are likely duplicates of one another.