openj9
openj9 copied to clipboard
eclipse-openj9
DaaLoadTest_daa1_special_5m_29_FAILED net.openj9.test.decimals.TestDecimalData NPE at java.base/java.util.regex.Pattern.matcher(Pattern.java:1132)
Failure link
From internal Test_openjdk11_j9_special.system_s390x_linux_testList_5 (rtj-ubu24s390x-svl-test-10ukx-1)
java version "11.0.25-beta" 2024-10-15
IBM Semeru Runtime Certified Edition 11.0.25+7-202410012208 (build 11.0.25-beta+7-202410012208)
Eclipse OpenJ9 VM 11.0.25+7-202410012208 (build master-047e551042, JRE 11 Linux s390x-64-Bit Compressed References 20241001_944 (JIT enabled, AOT enabled)
OpenJ9 - 047e551042
OMR - fa23d1b84
JCL - 66845860ec based on jdk-11.0.25+7)
Rerun in Grinder - Change TARGET to run only the failed test targets
Optional info
Failure output (captured from console output)
[2024-10-01T23:55:34.542Z] variation: -Xgcpolicy:gencon -Xgc:dynamicBreadthFirstScanOrdering
[2024-10-01T23:55:34.542Z] JVM_OPTIONS: -Xgcpolicy:gencon -Xgc:dynamicBreadthFirstScanOrdering
[2024-10-01T23:55:34.544Z] DLT 16:55:20.638 - First failure detected by thread: load-0. Not creating dumps as no dump generation is requested for this load test
[2024-10-01T23:55:34.544Z] DLT 16:55:20.640 - Test failed
[2024-10-01T23:55:34.544Z] DLT Failure num. = 1
[2024-10-01T23:55:34.544Z] DLT Test number = 13
[2024-10-01T23:55:34.544Z] DLT Test details = 'JUnit[net.openj9.test.decimals.TestDecimalData]'
[2024-10-01T23:55:34.544Z] DLT Suite number = 0
[2024-10-01T23:55:34.544Z] DLT Thread number = 0
[2024-10-01T23:55:34.544Z] DLT >>> Captured test output >>>
[2024-10-01T23:55:34.544Z] DLT Test failed:
[2024-10-01T23:55:34.544Z] DLT java.lang.NullPointerException
[2024-10-01T23:55:34.544Z] DLT at java.base/java.util.regex.Pattern.matcher(Pattern.java:1132)
[2024-10-01T23:55:34.544Z] DLT at java.base/java.util.Formatter.parse(Formatter.java:2700)
[2024-10-01T23:55:34.544Z] DLT at java.base/java.util.Formatter.format(Formatter.java:2655)
[2024-10-01T23:55:34.544Z] DLT at java.base/java.util.Formatter.format(Formatter.java:2609)
[2024-10-01T23:55:34.544Z] DLT at java.base/java.lang.String.format(String.java:3758)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runner.Description.formatDisplayName(Description.java:114)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runner.Description.createTestDescription(Description.java:86)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:96)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:57)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runners.Suite.describeChild(Suite.java:123)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runners.Suite.describeChild(Suite.java:27)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runner.JUnitCore.run(JUnitCore.java:136)
[2024-10-01T23:55:34.544Z] DLT at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[2024-10-01T23:55:34.544Z] DLT at net.adoptopenjdk.loadTest.adaptors.JUnitAdaptor.executeTest(JUnitAdaptor.java:130)
[2024-10-01T23:55:34.544Z] DLT at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
[2024-10-01T23:55:34.544Z] DLT at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
[2024-10-01T23:55:34.544Z] DLT at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
[2024-10-01T23:55:34.544Z] DLT at java.base/java.lang.Thread.run(Thread.java:839)
[2024-10-01T23:55:34.544Z] DLT <<<
[2024-10-01T23:55:34.544Z] DaaLoadTest_daa1_special_5m_29_FAILED
50x internal Grinder - 1/20 failed
Issue Number: 20283 Status: Open Recommended Components: comp:test, comp:gc, comp:vm Recommended Assignees: pshipton, jasonfengj9, hangshao0
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}
It was duplicated once in the grinder giving 1/20 failure rate. The grinder didn't finish because jenkins restarted. Try again.
50x internal Grinder - failed 2/50
@hzongaro fyi. The failure rate isn't quite high enough to make it a priority, but I put it into the next milestone plan anyway. Feel free to re-prioritize.
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_1/887 DaaLoadTest_daa1_5m_1
03:01:04 DLT class net.openj9.test.PDMoveShifts.TestShiftsAndConvert Total: 64 Fail: 4 Ignore: 0
03:01:04 DLT FAILURE: testShiftRightSimple(net.openj9.test.PDMoveShifts.TestShiftsAndConvert) - null
03:01:04 DLT FAILURE: testShiftLeftSimpleRandom(net.openj9.test.PDMoveShifts.TestShiftsAndConvert) - null
03:01:04 DLT FAILURE: testShiftRightHigherDstPrec(net.openj9.test.PDMoveShifts.TestShiftsAndConvert) - null
03:01:04 DLT FAILURE: testShiftRightSimpleRound(net.openj9.test.PDMoveShifts.TestShiftsAndConvert) - null
03:01:04 DLT Test failed:
03:01:04 DLT java.lang.NullPointerException
03:01:04 DLT at java.base/java.util.regex.Pattern.matcher(Pattern.java:1132)
03:01:04 DLT at java.base/java.util.Formatter.parse(Formatter.java:2700)
03:01:04 DLT at java.base/java.util.Formatter.format(Formatter.java:2655)
03:01:04 DLT at java.base/java.util.Formatter.format(Formatter.java:2609)
03:01:04 DLT at java.base/java.lang.String.format(String.java:3758)
03:01:04 DLT at org.junit.runner.Description.formatDisplayName(Description.java:114)
03:01:04 DLT at org.junit.runner.Description.createTestDescription(Description.java:86)
03:01:04 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:96)
03:01:04 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:57)
03:01:04 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
03:01:04 DLT at org.junit.runners.Suite.describeChild(Suite.java:123)
03:01:04 DLT at org.junit.runners.Suite.describeChild(Suite.java:27)
03:01:04 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
03:01:04 DLT at org.junit.runner.JUnitCore.run(JUnitCore.java:136)
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.system_s390x_linux_Nightly_testList_2/893 DaaLoadTest_all_CS_5m_0
00:52:31 DLT java.lang.NullPointerException
00:52:31 DLT at java.base/java.util.regex.Pattern.matcher(Pattern.java:1132)
00:52:31 DLT at java.base/java.util.Formatter.parse(Formatter.java:2700)
00:52:31 DLT at java.base/java.util.Formatter.format(Formatter.java:2655)
00:52:31 DLT at java.base/java.util.Formatter.format(Formatter.java:2609)
00:52:31 DLT at java.base/java.lang.String.format(String.java:3758)
00:52:31 DLT at org.junit.runner.Description.formatDisplayName(Description.java:114)
00:52:31 DLT at org.junit.runner.Description.createTestDescription(Description.java:86)
00:52:31 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:96)
00:52:31 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:57)
00:52:31 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
00:52:31 DLT at org.junit.runners.Suite.describeChild(Suite.java:123)
00:52:31 DLT at org.junit.runners.Suite.describeChild(Suite.java:27)
00:52:31 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
00:52:31 DLT at org.junit.runner.JUnitCore.run(JUnitCore.java:136)
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_1/894/ DaaLoadTest_daa1_CS_5m_0
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_0/896
@a7ehuo, as we discussed off-line, may I ask you to determine whether this is an optimizer problem or a code generation problem?
The NPE is from java/util/regex/Pattern.matcher(Ljava/lang/CharSequence;)Ljava/util/regex/Matcher; which is inlined into java/util/Formatter.parse(Ljava/lang/String;)Ljava/util/List;. The same as @hzongaro has observed, once -Xjit:{java/util/Formatter.parse?Ljava/lang/String??Ljava/util/List?}\(traceFull,traceILGen,traceCG,log=jitlog\) option is added to collect logs, the issue goes away: 90x in Grinder with logging all passed. Somehow with logging, the compilation takes longer and gets interrupted before it even completes. I'll try limit number of inlined methods and see if might help repro the issue with logging
I'm still not able to reproduce the NPE with tracing enabled, but I found something in the jitdump log that is related to generalStoreSinking.
With pc=0x000003FF6F0C5501, I find the sequence of instructions that lead up to the PC when the NPE happens [1]. It deferences r2. I find the same pattern of the sequence of instructions in the jitdump log [2]. Based on the jitdump log, the sequence of instructions are from block_2585 [3]. n37151n in block_2585 deferences an array #2995 to get the arraylength, hence 4(%r2) [5].
Before generalStoreSinking, in block_2578, n37135n stores #3038 into #2995. #3038 is an object of java/lang/String.value which is a byte array. block_2585 that is an extended block of block_2578 loads #2995 at n37150n.
After generalStoreSinking, n37135n that stores #3038 into #2995 is moved down into block_282 which is an EBB of block_2585. So when n37150n loads #2995 in block_2585, #2995 has not been initialized. This looks incorrect to me.
Two things I don't have an explanation so far
(1) This sequence of instructions are from inlining java/lang/String.lengthInternal()I into java/util/Formatter.parse(Ljava/lang/String;)Ljava/util/List;. Not sure why it says NPE is from java/util/regex/Pattern.matcher(Ljava/lang/CharSequence;)Ljava/util/regex/Matcher;.
(2) generalStoreSinking code hasn't been changed for years. Not sure why the problem happens now
[1] JIT'd code when NPE happens
0x3ff6f0c54c4 {java/util/Formatter.parse} +5584 c021020572f8 lgfi %r2, 0x20572f8 Ptr Obj - {java/lang/String$StringCompressionFlag}T
0x3ff6f0c54ca {java/util/Formatter.parse} +5590 e30020000004 lg %r0, 0(%r2)
0x3ff6f0c54d0 {java/util/Formatter.parse} +5596 c021020572f8 lgfi %r2, 0x20572f8 Ptr Obj - {java/lang/String$StringCompressionFlag}T
0x3ff6f0c54d6 {java/util/Formatter.parse} +5602 e3b020000004 lg %r11, 0(%r2)
0x3ff6f0c54dc {java/util/Formatter.parse} +5608 e32050c80004 lg %r2, 0xc8(%r5)
0x3ff6f0c54e2 {java/util/Formatter.parse} +5614 58008004 l %r0, 4(%r8) <<< ^+12646
0x3ff6f0c54e6 {java/util/Formatter.parse} +5618 184a lr %r4, %r10
0x3ff6f0c54e8 {java/util/Formatter.parse} +5620 a547001f nill %r4, 0x1f
0x3ff6f0c54ec {java/util/Formatter.parse} +5624 88004000 srl %r0, 0(%r4)
0x3ff6f0c54f0 {java/util/Formatter.parse} +5628 1b06 sr %r0, %r6
0x3ff6f0c54f2 {java/util/Formatter.parse} +5630 c20d0054c563 cfi %r0, 0x54c563
0x3ff6f0c54f8 {java/util/Formatter.parse} +5636 -1024:8704 a72420a2 jh 0x3ff6f0c963c C>> +22344 //
0x3ff6f0c54fc {java/util/Formatter.parse} +5640 501050bc st %r1, 0xbc(%r5)
0x3ff6f0c5500 {java/util/Formatter.parse} +5644 58002004 l %r0, 4(%r2) //<------ NPE
0x3ff6f0c5504 {java/util/Formatter.parse} +5648 584050c0 l %r4, 0xc0(%r5)
[2] jitdump log
0x3ff6f0d7fc4 000015d0 [ 0x3ff0a9b3490] c0 21 02 05 72 f8 LGFI GPR2,33911544
0x3ff6f0d7fca 000015d6 [ 0x3ff0a9b35a0] e3 00 20 00 00 04 LG GPR0, Static[java/lang/String.compressionFlag Ljava/lang/String$StringCompressionFlag;] 0(GPR2)
0x3ff6f0d7fd0 000015dc [ 0x3ff0a9b3870] fence Relative [ 000003FF4D6B4E04 ] BBEnd </block_2692>
0x3ff6f0d7fd0 000015dc [ 0x3ff0a9b39f0] fence Relative [ 000003FF17DAF6C0 ] BBStart <block_3122> (frequency 5530) (extension of previous block) (cold) (in loop 3146)
0x3ff6f0d7fd0 000015dc [ 0x3ff0a9b3d80] c0 21 02 05 72 f8 LGFI GPR2,33911544
0x3ff6f0d7fd6 000015e2 [ 0x3ff0a9b3e90] e3 b0 20 00 00 04 LG GPR11, Static[java/lang/String.compressionFlag Ljava/lang/String$StringCompressionFlag;] 0(GPR2)
0x3ff6f0d7fdc 000015e8 [ 0x3ff0a9b4160] fence Relative [ 000003FF17DAF6C4 ] BBEnd </block_3122>
0x3ff6f0d7fdc 000015e8 [ 0x3ff0a9b42e0] fence Relative [ 000003FF1584F9B0 ] BBStart <block_3189> (frequency 5530) (extension of previous block) (cold) (in loop 3146)
0x3ff6f0d7fdc 000015e8 [ 0x3ff0a9b4670] e3 20 50 c8 00 04 LG GPR2, Auto[<temp slot 126>] 200(GPR5)
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b4a10] fence Relative [ 000003FF1584F9B4 ] BBEnd </block_3189>
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b4fe0] assocreg
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b5900] assocreg
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b5330] DEPEND
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b6310] Label L0283:
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b7030] assocreg
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b6a60] DEPEND
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b7100] fence Relative [ 000003FF4ECAB350 ] BBStart <block_2578> (frequency 5530) (cold) (in loop 2578)
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b83f0] assocreg
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b7e20] VGNOP Label L0142, labelTargetAddr=0x000003FF6F0DC13C
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b8660] fence Relative [ 000003FF4ECAB354 ] BBEnd </block_2578>
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b87e0] fence Relative [ 000003FF4ECAB0B0 ] BBStart <block_2579> (frequency 5530) (extension of previous block) (cold) (in loop 2578)
0x3ff6f0d7fe2 000015ee [ 0x3ff0a9b8c50] 58 00 80 04 L GPR0, Shadow[<contiguous-array-size>] 4(GPR8)
0x3ff6f0d7fe6 000015f2 [ 0x3ff0a9b8e00] 18 4a LR GPR4,GPR10 ; LR=Clobber_eval
0x3ff6f0d7fe8 000015f4 [ 0x3ff0a9b8f00] a5 47 00 1f NILL GPR4,0x1f
0x3ff6f0d7fec 000015f8 [ 0x3feff329a50] 88 00 40 00 SRL GPR0,#3682 0(GPR4)
0x3ff6f0d7ff0 000015fc [ 0x3ff0a9b9180] 1b 06 SR GPR0,GPR6
0x3ff6f0d7ff2 000015fe [ 0x3ff0a9b9260] c2 0d 00 54 c5 63 CFI GPR0,5555555
0x3ff6f0d7ff8 00001604 [ 0x3ff0a9b9bb0] assocreg
0x3ff6f0d7ff8 00001604 [ 0x3ff0a9b95f0] a7 24 3f 70 BRC BL(0x2), Label L0142, labelTargetAddr=0x000003FF6F0DC13C
0x3ff6f0d7ffc 00001608 [ 0x3ff0a9b9fe0] fence Relative [ 000003FF4ECAB0B4 ] BBEnd </block_2579>
0x3ff6f0d7ffc 00001608 [ 0x3ff0a9ba160] fence Relative [ 000003FF4ECAA630 ] BBStart <block_2585> (frequency 5530) (extension of previous block) (cold) (in loop 2578)
0x3ff6f0d7ffc 00001608 [ 0x3ff0a9ba450] 50 10 50 bc ST GPR1, Auto[i<auto slot 4>] 188(GPR5)
0x3ff6f0d8000 0000160c [ 0x3ff0a9ba990] 58 00 20 04 L GPR0, Shadow[<contiguous-array-size>] 4(GPR2) //<----
0x3ff6f0d8004 00001610 [ 0x3ff0a9baca0] 58 40 50 c0 L GPR4, Auto[<temp slot 127>] 192(GPR5)
[3]
------------------------------
n37154n ( 0) treetop [ 0x3ff4ec84d30] bci=[33,15,2292] rc=0 vc=4509 vn=- li=2585 udi=- nc=1
n37153n ( 0) iushr (in GPR_ 0x3ff0a9baa60) (X>=0 cannotOverflow ) [ 0x3ff4ec84ce0] bci=[33,15,2292] rc=0 vc=4509 vn=- li=2585 udi=- nc=2 flg=0x1100
n37151n ( 0) iloadi <contiguous-array-size>[#309 Shadow +4] [flags 0x603 0x0 ] (in GPR_ 0x3ff0a9ba920) (X>=0 cannotOverflow ) [ 0x3ff4ec84c40] bci=[33,10,2292] rc=0 vc=4509 vn=- li=2585 udi=- nc=1 flg=0x1100
n51662n ( 1) ==>aRegLoad (in &GPR_ 0x3ff0a9b6460) (X!=0 SeenRealReference )
n37152n ( 0) iload <temp slot 127>[#2996 Auto] [flags 0x3 0x0 ] (in GPR_ 0x3ff0a9bac30) (cannotOverflow ) [ 0x3ff4ec84c90] bci=[33,12,2292] rc=0 vc=4509 vn=- li=2585 udi=- nc=0 flg=0x1000
------------------------------
[ 0x3ff0a9ba990] L GPR_ 0x3ff0a9ba920, Shadow[<contiguous-array-size>] 4(&GPR_ 0x3ff0a9b6460)
[ 0x3ff0a9baca0] L GPR_ 0x3ff0a9bac30, Auto[<temp slot 127>] ?+0(GPR5)
[ 0x3ff0a9bad70] NILL GPR_ 0x3ff0a9bac30,0x1f
[ 0x3ff0a9baf10] SRLK GPR_ 0x3ff0a9baa60,GPR_ 0x3ff0a9ba920,#3683 0(GPR_ 0x3ff0a9bac30)
[4] Before generalStoreSinking
n37187n BBStart <block_2578> (freq 5530) (cold) (in loop 2578) [ 0x3ff4ec85780] bci=[-1,0,2699] rc=0 vc=9798 vn=- li=- udi=- nc=0
n37119n ificmpne --> block_2573 BBStart at n37084n (OSRGuard/DummyTest ) [ 0x3ff4ec84240] bci=[-1,0,2699] rc=0 vc=9798 vn=- li=- udi=- nc=2 flg=0x1028
n37120n iload unknown static[#2278 Static] [flags 0x10303 0x0 ] (cannotOverflow ) [ 0x3ff4ec84290] bci=[31,54,2728] rc=1 vc=9798 vn=- li=- udi=- nc=0 flg=0x1008
n37121n iconst 0 (X==0 X>=0 X<=0 ) [ 0x3ff4ec842e0] bci=[31,54,2728] rc=1 vc=9798 vn=- li=- udi=- nc=0 flg=0x302
n37188n BBEnd </block_2578> (cold) [ 0x3ff4ec857d0] bci=[32,2,1323] rc=0 vc=9798 vn=- li=- udi=- nc=0
n37182n BBStart <block_2579> (freq 5530) (extension of previous block) (cold) (in loop 2578) [ 0x3ff4ec855f0] bci=[32,2,1323] rc=0 vc=9798 vn=- li=- udi=- nc=0
n37135n astore <temp slot 126>[#2995 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x3ff4ec84740] bci=[33,7,2292] rc=0 vc=9798 vn=- li=- udi=74 nc=1 flg=0x4
n37134n aload <temp slot 168>[#3038 Auto] [flags 0x7 0x0 ] (X!=0 createdByPRE ) [ 0x3ff4ec846f0] bci=[33,7,2292] rc=2 vc=9798 vn=- li=- udi=106 nc=0 flg=0x40004
n37141n istore <temp slot 127>[#2996 Auto] [flags 0x3 0x0 ] [ 0x3ff4ec84920] bci=[33,12,2292] rc=0 vc=9798 vn=- li=- udi=75 nc=1
n37140n iload <temp slot 170>[#3040 Auto] [flags 0x3 0x0 ] (cannotOverflow createdByPRE ) [ 0x3ff4ec848d0] bci=[33,12,2292] rc=2 vc=9798 vn=- li=- udi=107 nc=0 flg=0x41000
n37149n ificmpgt --> block_2573 BBStart at n37084n (maxLoopIternGuard ) [ 0x3ff4ec84ba0] bci=[33,15,2292] rc=0 vc=9798 vn=- li=- udi=- nc=2 flg=0x820
n37147n isub (cannotOverflow ) [ 0x3ff4ec84b00] bci=[33,15,2292] rc=1 vc=9798 vn=- li=- udi=- nc=2 flg=0x1000
n37145n iushr (X>=0 cannotOverflow ) [ 0x3ff4ec84a60] bci=[33,15,2292] rc=1 vc=9798 vn=- li=- udi=- nc=2 flg=0x1100
n37143n arraylength (stride 1) (X>=0 cannotOverflow ) [ 0x3ff4ec849c0] bci=[33,10,2292] rc=1 vc=9798 vn=- li=- udi=- nc=1 flg=0x1100
n37134n ==>aload
n37140n ==>iload
n37146n iload i<auto slot 3>[#1074 Auto] [flags 0x3 0x0 ] (X>=0 cannotOverflow ) [ 0x3ff4ec84ab0] bci=[32,5,1323] rc=1 vc=9798 vn=- li=- udi=108 nc=0 flg=0x1100
n37148n iconst 0x54c563 (X!=0 X>=0 ) [ 0x3ff4ec84b50] bci=[33,15,2292] rc=1 vc=9798 vn=- li=- udi=- nc=0 flg=0x104
n37167n BBEnd </block_2579> (cold) [ 0x3ff4ec85140] bci=[32,2,1323] rc=0 vc=9798 vn=- li=- udi=- nc=0
n37164n BBStart <block_2585> (freq 5530) (extension of previous block) (cold) (in loop 2578) [ 0x3ff4ec85050] bci=[32,2,1323] rc=0 vc=9798 vn=- li=- udi=- nc=0
n37154n istore <temp slot 128>[#2997 Auto] [flags 0x3 0x0 ] [ 0x3ff4ec84d30] bci=[33,15,2292] rc=0 vc=9798 vn=- li=- udi=76 nc=1
n37153n iushr (X>=0 cannotOverflow ) [ 0x3ff4ec84ce0] bci=[33,15,2292] rc=1 vc=9798 vn=- li=- udi=- nc=2 flg=0x1100
n37151n arraylength (stride 1) (X>=0 cannotOverflow ) [ 0x3ff4ec84c40] bci=[33,10,2292] rc=1 vc=9798 vn=- li=- udi=- nc=1 flg=0x1100
n37150n aload <temp slot 126>[#2995 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x3ff4ec84bf0] bci=[33,7,2292] rc=1 vc=9798 vn=- li=- udi=109 nc=0 flg=0x4
n37152n iload <temp slot 127>[#2996 Auto] [flags 0x3 0x0 ] (cannotOverflow ) [ 0x3ff4ec84c90] bci=[33,12,2292] rc=1 vc=9798 vn=- li=- udi=110 nc=0 flg=0x1000
n37165n BBEnd </block_2585> (cold) [ 0x3ff4ec850a0] bci=[32,2,1323] rc=0 vc=9798 vn=- li=- udi=- nc=0
[5]
[ 23570] O^O SINK STORES: Finding placements for store [000003FF4EC84740] with tree depth 2
title="Trees after generalStoreSinking"
n37187n BBStart <block_2578> (freq 5530) (cold) [ 0x3ff4ec85780] bci=[-1,0,2699] rc=0 vc=3 vn=- li=- udi=- nc=0
n37119n ificmpne --> block_2573 BBStart at n37084n (OSRGuard/DummyTest ) [ 0x3ff4ec84240] bci=[-1,0,2699] rc=0 vc=2599 vn=- li=- udi=- nc=2 flg=0x1028
n37120n iload unknown static[#2278 Static] [flags 0x10303 0x0 ] (cannotOverflow ) [ 0x3ff4ec84290] bci=[31,54,2728] rc=1 vc=2599 vn=- li=- udi=- nc=0 flg=0x1008
n37121n iconst 0 (X==0 X>=0 X<=0 ) [ 0x3ff4ec842e0] bci=[31,54,2728] rc=1 vc=2599 vn=- li=- udi=- nc=0 flg=0x302
n37188n BBEnd </block_2578> (cold) [ 0x3ff4ec857d0] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n37182n BBStart <block_2579> (freq 5530) (extension of previous block) (cold) [ 0x3ff4ec855f0] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n37141n treetop [ 0x3ff4ec84920] bci=[33,12,2292] rc=0 vc=2586 vn=- li=- udi=75 nc=1
n37140n iload <temp slot 170>[#3040 Auto] [flags 0x3 0x0 ] (cannotOverflow createdByPRE ) [ 0x3ff4ec848d0] bci=[33,12,2292] rc=2 vc=2586 vn=- li=- udi=107 nc=0 flg=0x41000
n37149n ificmpgt --> block_2573 BBStart at n37084n (maxLoopIternGuard ) [ 0x3ff4ec84ba0] bci=[33,15,2292] rc=0 vc=2585 vn=- li=- udi=- nc=2 flg=0x820
n37147n isub (cannotOverflow ) [ 0x3ff4ec84b00] bci=[33,15,2292] rc=1 vc=2585 vn=- li=- udi=- nc=2 flg=0x1000
n37145n iushr (X>=0 cannotOverflow ) [ 0x3ff4ec84a60] bci=[33,15,2292] rc=1 vc=2585 vn=- li=- udi=- nc=2 flg=0x1100
n37143n arraylength (stride 1) (X>=0 cannotOverflow ) [ 0x3ff4ec849c0] bci=[33,10,2292] rc=1 vc=2585 vn=- li=- udi=- nc=1 flg=0x1100
n37134n aload <temp slot 168>[#3038 Auto] [flags 0x7 0x0 ] (X!=0 createdByPRE ) [ 0x3ff4ec846f0] bci=[33,7,2292] rc=2 vc=2587 vn=- li=- udi=106 nc=0 flg=0x40004
n37140n ==>iload
n37146n iload i<auto slot 3>[#1074 Auto] [flags 0x3 0x0 ] (X>=0 cannotOverflow ) [ 0x3ff4ec84ab0] bci=[32,5,1323] rc=1 vc=2585 vn=- li=- udi=108 nc=0 flg=0x1100
n37148n iconst 0x54c563 (X!=0 X>=0 ) [ 0x3ff4ec84b50] bci=[33,15,2292] rc=1 vc=2585 vn=- li=- udi=- nc=0 flg=0x104
n37167n BBEnd </block_2579> (cold) [ 0x3ff4ec85140] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n37164n BBStart <block_2585> (freq 5530) (extension of previous block) (cold) [ 0x3ff4ec85050] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n37154n treetop [ 0x3ff4ec84d30] bci=[33,15,2292] rc=0 vc=2584 vn=- li=- udi=76 nc=1
n37153n iushr (X>=0 cannotOverflow ) [ 0x3ff4ec84ce0] bci=[33,15,2292] rc=1 vc=2584 vn=- li=- udi=- nc=2 flg=0x1100
n37151n arraylength (stride 1) (X>=0 cannotOverflow ) [ 0x3ff4ec84c40] bci=[33,10,2292] rc=1 vc=2584 vn=- li=- udi=- nc=1 flg=0x1100
n37150n aload <temp slot 126>[#2995 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x3ff4ec84bf0] bci=[33,7,2292] rc=1 vc=2584 vn=- li=- udi=109 nc=0 flg=0x4
n37152n iload <temp slot 127>[#2996 Auto] [flags 0x3 0x0 ] (cannotOverflow ) [ 0x3ff4ec84c90] bci=[33,12,2292] rc=1 vc=2584 vn=- li=- udi=110 nc=0 flg=0x1000
n37165n BBEnd </block_2585> (cold) [ 0x3ff4ec850a0] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n36818n BBStart <block_2532> (freq 5530) (extension of previous block) (cold) (loop pre-header) [ 0x3ff4f2ae420] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n36819n BBEnd </block_2532> (cold) [ 0x3ff4f2ae470] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n6439n BBStart <block_280> (freq 5530) (extension of previous block) (cold) [ 0x3ff65bccc60] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n6459n ifacmpne --> block_281 BBStart at n6457n (swappedChildren ) [ 0x3ff65bcd2a0] bci=[32,23,1325] rc=0 vc=2582 vn=- li=- udi=- nc=2 flg=0x20020
n6456n aload <temp slot 172>[#3042 Auto] [flags 0x7 0x0 ] (createdByPRE ) [ 0x3ff65bcd1b0] bci=[32,20,1325] rc=1 vc=2582 vn=- li=- udi=113 nc=0 flg=0x40000
n6455n aconst NULL (X==0 ) [ 0x3ff65bcd160] bci=[32,19,1325] rc=1 vc=2582 vn=- li=- udi=- nc=0 flg=0x2
n6440n BBEnd </block_280> (cold) [ 0x3ff65bcccb0] bci=[32,23,1325] rc=0 vc=3 vn=- li=- udi=- nc=0
n47194n BBStart <block_2761> (freq 5530) (extension of previous block) (cold) (loop pre-header) [ 0x3ff421d8f70] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n47195n BBEnd </block_2761> (cold) [ 0x3ff421d8fc0] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n6422n BBStart <block_282> (freq 5530) (extension of previous block) (cold) [ 0x3ff65bcc710] bci=[32,2,1323] rc=0 vc=3 vn=- li=- udi=- nc=0
n37135n astore <temp slot 126>[#2995 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x3ff4ec84740] bci=[33,7,2292] rc=0 vc=2587 vn=- li=- udi=74 nc=1 flg=0x4
n37134n ==>aload
@a7ehuo, I haven't looked at the IL in detail, but does the pattern look similar to the IL that appears in this comment in issue 17515? If so, I have a prototype fix for that problem, and I can try to see whether it resolves the problem for this test failure. I haven't managed to spend the time needed to analyze my fix to verify its correctness.
@hzongaro The transformation by generalStoreSinking in this issue looks similar to the comments in issue 17515.
#2995 in this issue is #3463 in issue 17515.
Store node n37154n in this issue is store node n54003n in issue 17515.
Before generalStoreSinking, first n37135n stores a value into #2995. And then #2995 is only loaded once (n37150n) under n37154n istore. After generalStoreSinking, the store node n37135n is moved after n37154n istore.
n37135n astore <temp slot 126>[#2995 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x3ff4ec84740] bci=[33,7,2292] rc=0 vc=9798 vn=- li=- udi=74 nc=1 flg=0x4
n37134n aload <temp slot 168>[#3038 Auto] [flags 0x7 0x0 ] (X!=0 createdByPRE ) [ 0x3ff4ec846f0] bci=[33,7,2292] rc=2 vc=9798 vn=- li=- udi=106 nc=0 flg=0x40004
n37141n
...
n37154n istore <temp slot 128>[#2997 Auto] [flags 0x3 0x0 ] [ 0x3ff4ec84d30] bci=[33,15,2292] rc=0 vc=9798 vn=- li=- udi=76 nc=1
n37153n iushr (X>=0 cannotOverflow ) [ 0x3ff4ec84ce0] bci=[33,15,2292] rc=1 vc=9798 vn=- li=- udi=- nc=2 flg=0x1100
n37151n arraylength (stride 1) (X>=0 cannotOverflow ) [ 0x3ff4ec84c40] bci=[33,10,2292] rc=1 vc=9798 vn=- li=- udi=- nc=1 flg=0x1100
n37150n aload <temp slot 126>[#2995 Auto] [flags 0x7 0x0 ] (X!=0 ) [ 0x3ff4ec84bf0] bci=[33,7,2292] rc=1 vc=9798 vn=- li=- udi=109 nc=0 flg=0x4
n37152n iload <temp slot 127>[#2996 Auto] [flags 0x3 0x0 ] (cannotOverflow ) [ 0x3ff4ec84c90] bci=[33,12,2292] rc=1 vc=9798 vn=- li=- udi=110 nc=0 flg=0x1000
It seems my prototype fix did not resolve the problem. An internal grinder run yielded 4 failures in a 5x30 run. I'll investigate further to determine whether my fix is incomplete or if there is some additional problem.
A second internal grinder run with -XX:+MergeCompilerOptions -Xjit:{*Formatter.parse*}\(disableStoreSinking\) had no failures, so that’s some evidence that General Store Sinking might be the only problem.
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_0/914 DaaLoadTest_daa1_CS_5m_0
02:38:13 DLT class net.openj9.test.PDMoveShifts.TestShiftsAndConvert Total: 64 Fail: 1 Ignore: 0
02:38:13 DLT FAILURE: testShiftRightSimpleRound(net.openj9.test.PDMoveShifts.TestShiftsAndConvert) - null
02:38:13 DLT Test failed:
02:38:13 DLT java.lang.NullPointerException
02:38:13 DLT at java.base/java.util.regex.Pattern.matcher(Pattern.java:1132)
02:38:13 DLT at java.base/java.util.Formatter.parse(Formatter.java:2700)
02:38:13 DLT at java.base/java.util.Formatter.format(Formatter.java:2655)
02:38:13 DLT at java.base/java.util.Formatter.format(Formatter.java:2609)
02:38:13 DLT at java.base/java.lang.String.format(String.java:3758)
02:38:13 DLT at org.junit.runner.Description.formatDisplayName(Description.java:114)
02:38:13 DLT at org.junit.runner.Description.createTestDescription(Description.java:86)
02:38:13 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:96)
02:38:13 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:57)
02:38:13 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
02:38:13 DLT at org.junit.runners.Suite.describeChild(Suite.java:123)
02:38:13 DLT at org.junit.runners.Suite.describeChild(Suite.java:27)
02:38:13 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
02:38:13 DLT at org.junit.runner.JUnitCore.run(JUnitCore.java:136)
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_0/918 DaaLoadTest_daa1_CS_5m_0
03:52:36 DLT 08:52:35.005 - Completed 14.0%. Number of tests started=382 (+193)
03:52:36 DLT 08:52:35.880 - First failure detected by thread: load-1. Not creating dumps as no dump generation is requested for this load test
03:52:36 DLT 08:52:35.880 - Test failed
03:52:36 DLT Failure num. = 1
03:52:36 DLT Test number = 2
03:52:36 DLT Test details = 'JUnit[net.openj9.test.arithmetics.TestArithmeticOperations]'
03:52:36 DLT Suite number = 0
03:52:36 DLT Thread number = 1
03:52:36 DLT >>> Captured test output >>>
03:52:36 DLT Test failed:
03:52:36 DLT java.lang.NullPointerException
03:52:36 DLT at java.base/java.util.regex.Pattern.matcher(Pattern.java:1132)
03:52:36 DLT at java.base/java.util.Formatter.parse(Formatter.java:2700)
03:52:36 DLT at java.base/java.util.Formatter.format(Formatter.java:2655)
03:52:36 DLT at java.base/java.util.Formatter.format(Formatter.java:2609)
03:52:36 DLT at java.base/java.lang.String.format(String.java:3758)
03:52:36 DLT at org.junit.runner.Description.formatDisplayName(Description.java:114)
03:52:36 DLT at org.junit.runner.Description.createTestDescription(Description.java:86)
03:52:36 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:96)
03:52:36 DLT at org.junit.runners.BlockJUnit4ClassRunner.describeChild(BlockJUnit4ClassRunner.java:57)
03:52:36 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
03:52:36 DLT at org.junit.runners.Suite.describeChild(Suite.java:123)
03:52:36 DLT at org.junit.runners.Suite.describeChild(Suite.java:27)
03:52:36 DLT at org.junit.runners.ParentRunner.getDescription(ParentRunner.java:352)
03:52:36 DLT at org.junit.runner.JUnitCore.run(JUnitCore.java:136)
03:52:36 DLT at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
03:52:36 DLT at net.adoptopenjdk.loadTest.adaptors.JUnitAdaptor.executeTest(JUnitAdaptor.java:130)
03:52:36 DLT at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
03:52:36 DLT at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
03:52:36 DLT at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
03:52:36 DLT at java.base/java.lang.Thread.run(Thread.java:835)
03:52:36 DLT <<<
03:52:36 DLT
03:52:36 DLT 08:52:35.881 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.881 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.881 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.881 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.881 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.882 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.882 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.882 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.882 - Test failed. Details recorded in execution log.
03:52:36 DLT 08:52:35.882 - Number of test failures has reached 'AbortAtFailureLimit' (10). Terminating load test
03:52:36 DLT 08:52:35.882 - Thread completed. Suite=0 thread=1
03:52:36 DLT 08:52:36.363 - Thread completed. Suite=0 thread=0
03:52:36 DLT 08:52:36.433 - Load test completed
03:52:36 DLT 08:52:36.434 - Ran : 393
03:52:36 DLT 08:52:36.434 - Passed : 383
03:52:36 DLT 08:52:36.434 - Failed : 10
03:52:36 DLT 08:52:36.434 - Result : FAILED
03:52:36 DLT 08:52:36.434 - Note that only the first 1 failures have been reported
03:52:36 DLT 2024-11-22 08:52:36,443 pool-1-thread-1 ERROR Unable to unregister MBeans java.lang.NullPointerException
03:52:36 DLT at java.base/java.util.regex.Pattern.matcher(Pattern.java:1132)
03:52:36 DLT at java.base/java.util.Formatter.parse(Formatter.java:2700)
03:52:36 DLT at java.base/java.util.Formatter.format(Formatter.java:2655)
03:52:36 DLT at java.base/java.util.Formatter.format(Formatter.java:2609)
03:52:36 DLT at java.base/java.lang.String.format(String.java:3758)
03:52:36 DLT at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerContext(Server.java:260)
03:52:36 DLT at org.apache.logging.log4j.core.jmx.Server.unregisterLoggerContext(Server.java:249)
03:52:36 DLT at org.apache.logging.log4j.core.LoggerContext.stop(LoggerContext.java:379)
03:52:36 DLT at org.apache.logging.log4j.core.LoggerContext$1.run(LoggerContext.java:320)
03:52:36 DLT at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry$RegisteredCancellable.run(DefaultShutdownCallbackRegistry.java:119)
03:52:36 DLT at org.apache.logging.log4j.core.util.DefaultShutdownCallbackRegistry.run(DefaultShutdownCallbackRegistry.java:78)
03:52:36 DLT at java.base/java.lang.Thread.run(Thread.java:835)
03:52:36 DLT
03:52:36 STF 08:52:36.792 - **FAILED** Process DLT ended with exit code (1) and not the expected exit code/s (0)
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_0/919 https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.system_s390x_linux_Release_testList_2/124 - 0.49 release build https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.system_s390x_linux_Nightly_testList_2/922 https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_2/927 https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.system_s390x_linux_Release_testList_2/126 - 0.49 release https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_1/933 https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_1/936
I'll need to ensure the fix handles stores that have a non-zero reference count correctly. This will need to move out to 0.51.
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly_testList_0/954/
https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.system_s390x_linux_Release_testList_1/132 - 0.49 build