Openj9: system_s390x DaaLoadTest arithmetics.TestPerformance NumberFormatException

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_sanity.system_s390x_linux_Nightly/53
DaaLoadTest_daa1_0
Notice the input string contains a control character ^@ which I believe is a 0.

02:15:11.027 - Test failed
  Failure num.  = 1
  Test number   = 7
  Test details  = 'JUnit[net.openj9.test.arithmetics.TestPerformance]'
  Suite number  = 0
  Thread number = 0
>>> Captured test output >>>
testStarted : testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance)
java.lang.NumberFormatException: For input string: "3610941^@4"
    at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:68)
    at java.base/java.lang.Integer.parseInt(Integer.java:658)
    at java.base/java.math.BigInteger.<init>(BigInteger.java:544)
    at java.base/java.math.BigInteger.<init>(BigInteger.java:673)
    at net.openj9.test.Utils.toPrecision(Utils.java:498)
    at net.openj9.test.arithmetics.TestPerformance.getComparisionReferenceValue(TestPerformance.java:375)
    at net.openj9.test.arithmetics.TestPerformance.testEQ(TestPerformance.java:273)
    at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:86)
    at jdk.internal.reflect.GeneratedMethodAccessor123.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:567)
    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.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.junit.runners.Suite.runChild(Suite.java:128)
    at org.junit.runners.Suite.runChild(Suite.java:27)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
    at net.adoptopenjdk.loadTest.adaptors.JUnitAdaptor.executeTest(JUnitAdaptor.java:130)
    at net.adoptopenjdk.loadTest.LoadTestRunner$2.run(LoadTestRunner.java:182)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:831)

https://ci.eclipse.org/openj9//job/Grinder/parambuild/?JDK_VERSION=13&JDK_IMPL=openj9&BUILD_LIST=system&JenkinsFile=openjdk_s390x_linux&TARGET=DaaLoadTest_daa1_0&SDK_RESOURCE=upstream&CUSTOMIZED_SDK_URL=https://140-211-168-230-openstack.osuosl.org/artifactory/ci-eclipse-openj9/Build_JDK13_s390x_linux_Nightly/76/OpenJ9-JDK13-s390x_linux-20190929-023419.tar.gz

[pshipton]

5x grinder https://ci.eclipse.org/openj9/job/Grinder/527/ - failed 1

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly/156

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_extended.system_s390x_linux_Nightly/155
DaaLoadTest_all_0

[fjeremic]

OMR SHA is fd3d7a7:

02:12:26  openjdk version "13-internal" 2019-09-17
02:12:26  OpenJDK Runtime Environment (build 13-internal+0-adhoc.****.BuildJDK13s390xlinuxNightly)
02:12:26  Eclipse OpenJ9 VM (build master-230f0fa, JRE 13 Linux s390x-64-Bit Compressed References 20190928_76 (JIT enabled, AOT enabled)
02:12:26  OpenJ9   - 230f0fa
02:12:26  OMR      - fd3d7a7
02:12:26  JCL      - cfc80e6 based on jdk-13+33)

Which contains the JProfiling change [1]. Given the failure rate and type of test [2] this is likely to reach profiling compiles and JProfiling commit seems most suspect to me. @r30shah can you please take a look at this one?

[1] https://github.com/eclipse/openj9-omr/commits/fd3d7a790ba4d78aba025aec953f8572770f7dfd
[2] https://github.com/eclipse/openj9-systemtest/blob/master/openj9.test.daa/src/test.daa/net/openj9/test/arithmetics/TestPerformance.java

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_extended.system_s390x_linux_Nightly/58
DaaLoadTest_all_ConcurrentScavenge_0
https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_special.system_s390x_linux_Personal/23
DaaLoadTest_daa3_special_22

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Personal/32
DaaLoadTest_daa3_special_22
DaaLoadTest_all_special_20

[fjeremic]

Just a quick update that we are actively investigating these issues in the background with high priority.

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_s390x_linux_Nightly/485
DaaLoadTest_daa1_special_22

DLT 03:58:27.974 - Test failed
DLT   Failure num.  = 1
DLT   Test number   = 7
DLT   Test details  = 'JUnit[net.openj9.test.arithmetics.TestPerformance]'
DLT   Suite number  = 0
DLT   Thread number = 0
DLT >>> Captured test output >>>
DLT testStarted : testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance)
DLT testFailure: testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance): multiplyPackedDecimal: arrays first differed at element [2]; expected:<37> but was:<0>
DLT multiplyPackedDecimal: arrays first differed at element [2]; expected:<37> but was:<0>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Assert.java:341)
DLT     at net.openj9.test.arithmetics.TestPerformance.verify(TestPerformance.java:465)
DLT     at net.openj9.test.arithmetics.TestPerformance.testMul(TestPerformance.java:161)
DLT     at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:78)

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Personal/44
DaaLoadTest_daa1_special_22

[fjeremic]

We are still working on tracking down this issue. It has been very problematic as the issue disappears as soon as we try to log anything. The timing is very sensitive. We are coming up with some ways of dealing with this at the moment.

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly/180
DaaLoadTest_daa1_0

DLT   Failure num.  = 1
DLT   Test number   = 7
DLT   Test details  = 'JUnit[net.openj9.test.arithmetics.TestPerformance]'
DLT   Suite number  = 0
DLT   Thread number = 0
DLT >>> Captured test output >>>
DLT testStarted : testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance)
DLT testFailure: testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance): multiplyPackedDecimal: arrays first differed at element [5]; expected:<112> but was:<-16>
DLT multiplyPackedDecimal: arrays first differed at element [5]; expected:<112> but was:<-16>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Assert.java:341)
DLT     at net.openj9.test.arithmetics.TestPerformance.verify(TestPerformance.java:465)
DLT     at net.openj9.test.arithmetics.TestPerformance.testMul(TestPerformance.java:161)
DLT     at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:78)

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_sanity.system_s390x_linux_Nightly/182
DaaLoadTest_daa1_ConcurrentScavenge_0

DLT testFailure: testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance): remainderPackedDecimal: arrays first differed at element [6]; expected:<-127> but was:<0>
DLT remainderPackedDecimal: arrays first differed at element [6]; expected:<-127> but was:<0>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Assert.java:341)
DLT     at net.openj9.test.arithmetics.TestPerformance.verify(TestPerformance.java:465)
DLT     at net.openj9.test.arithmetics.TestPerformance.testRem(TestPerformance.java:202)
DLT     at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

[fjeremic]

Still working on this with @r30shah. We've now captured the failure successfully with a core dump and a JIT trace log when the issue happens. The trace file is massive (~50 method inlined into it) so it is a bit difficult to investigate the path we took to arrive at the failure but we'll get it done. Currently chugging through the CFG and looking at what could have gone wrong.

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_s390x_linux_Nightly/605
DaaLoadTest_daa1_special_22

DLT testFailure: testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance): remainderPackedDecimal: arrays first differed at element [6]; expected:<-111> but was:<0>
DLT remainderPackedDecimal: arrays first differed at element [6]; expected:<-111> but was:<0>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Assert.java:341)
DLT     at net.openj9.test.arithmetics.TestPerformance.verify(TestPerformance.java:465)
DLT     at net.openj9.test.arithmetics.TestPerformance.testRem(TestPerformance.java:202)
DLT     at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

[fjeremic]

Another update. We tracked down the bug last evening. It is definitely due to JProfiling.

Trees before JProfiling:

n1419n    BBStart <block_65> (freq 271) (extension of previous block)                         [0x50D80EAB40] bci=[10,1,484] rc=0 vc=11501 vn=- li=-1 udi=- nc=0
n1386n    iRegStore GPR6                                                                      [0x50D80EA0F0] bci=[10,1,484] rc=0 vc=11501 vn=- li=-1 udi=- nc=1
n1903n      ==>iconst 0
n1403n    ificmpgt --> block_404 BBStart at n5390n ()                                         [0x50D80EA640] bci=[10,8,485] rc=0 vc=11501 vn=- li=-1 udi=- nc=3 flg=0x20
n10944n     ==>iRegLoad
n1400n      iloadi  <array-shadow>[#237  Shadow] [flags 0xffffffff80000603 0x0 ] (cannotOverflow )  [0x50D80EA550] bci=[10,7,485] rc=1 vc=11501 vn=- li=- udi=- nc=1 flg=0x1000
n1399n        aladd (X>=0 internalPtr sharedMemory )                                          [0x50D80EA500] bci=[10,7,485] rc=1 vc=11501 vn=- li=- udi=- nc=2 flg=0x8100
n1388n          aload  java/lang/Integer.sizeTable [I[#610  final Static] [flags 0x20307 0x0 ] (X!=0 sharedMemory )  [0x50D80EA190] bci=[10,3,485] rc=1 vc=11501 vn=- li=- udi=- nc=0 flg=0x4n1398n          lconst 16 (highWordZero X!=0 X>=0 cannotOverflow )                            [0x50D80EA4B0] bci=[10,7,485] rc=1 vc=11501 vn=- li=- udi=- nc=0 flg=0x5104
n10963n     GlRegDeps ()                                                                      [0x50D8C75280] bci=[10,8,485] rc=1 vc=11501 vn=- li=- udi=- nc=5 flg=0x20
n10961n       PassThrough GPR6                                                                [0x50D8C751E0] bci=[-1,21,80] rc=1 vc=11501 vn=- li=- udi=- nc=1
n1903n          ==>iconst 0
n10962n       PassThrough GPR7                                                                [0x50D8C75230] bci=[3,72,411] rc=1 vc=11501 vn=- li=- udi=- nc=1
n10944n         ==>iRegLoad
n10942n       ==>aRegLoad
n10943n       ==>aRegLoad
n10944n       ==>iRegLoad
n1382n    BBEnd </block_65> =====                                                             [0x50D80E9FB0] bci=[10,8,485] rc=0 vc=11501 vn=- li=-1 udi=- nc=1

Trees after JProfiling:

n1419n    BBStart <block_65> (freq 271) (extension of previous block)                         [0x50D80EAB40] bci=[10,1,484] rc=0 vc=8 vn=- li=65 udi=- nc=0
n1403n    ificmpgt --> block_404 BBStart at n5390n ()                                         [0x50D80EA640] bci=[10,8,485] rc=0 vc=8 vn=- li=65 udi=- nc=3 flg=0x20
n13346n     ==>iRegLoad
n1400n      iloadi  <array-shadow>[#237  Shadow] [flags 0xffffffff80000603 0x0 ] (cannotOverflow )  [0x50D80EA550] bci=[10,7,485] rc=1 vc=8 vn=- li=65 udi=- nc=1 flg=0x1000
n1399n        aladd (X>=0 internalPtr sharedMemory )                                          [0x50D80EA500] bci=[10,7,485] rc=1 vc=8 vn=- li=65 udi=- nc=2 flg=0x8100
n1388n          aload  java/lang/Integer.sizeTable [I[#610  final Static] [flags 0x20307 0x0 ] (X!=0 sharedMemory )  [0x50D80EA190] bci=[10,3,485] rc=1 vc=8 vn=- li=65 udi=- nc=0 flg=0x4
n1398n          lconst 16 (highWordZero X!=0 X>=0 cannotOverflow )                            [0x50D80EA4B0] bci=[10,7,485] rc=1 vc=8 vn=- li=65 udi=- nc=0 flg=0x5104
n10963n     GlRegDeps ()                                                                      [0x50D8C75280] bci=[10,8,485] rc=1 vc=8 vn=- li=65 udi=- nc=5 flg=0x20
n10961n       PassThrough GPR6                                                                [0x50D8C751E0] bci=[-1,21,80] rc=1 vc=8 vn=- li=65 udi=- nc=1
n13343n         ==>iconst 0
n10962n       PassThrough GPR7                                                                [0x50D8C75230] bci=[3,72,411] rc=1 vc=8 vn=- li=65 udi=- nc=1
n13346n         ==>iRegLoad
n13344n       ==>aRegLoad
n13345n       ==>aRegLoad
n13346n       ==>iRegLoad
n1386n    iRegStore GPR6                                                                      [0x50D80EA0F0] bci=[10,1,484] rc=0 vc=8 vn=- li=65 udi=- nc=1
n13343n     ==>iconst 0
n13349n   iRegStore GPR7                                                                      [0x50D8563C50] bci=[3,72,411] rc=0 vc=8 vn=- li=65 udi=- nc=1
n13346n     ==>iRegLoad
n13350n   iRegStore GPR7                                                                      [0x50D8563CA0] bci=[3,72,411] rc=0 vc=8 vn=- li=65 udi=- nc=1
n13346n     ==>iRegLoad
n1382n    BBEnd </block_65> =====                                                             [0x50D80E9FB0] bci=[10,8,485] rc=0 vc=8 vn=- li=65 udi=- nc=1

The JProfiling post-GRA block splitter seems to have mutilated this block into an invalid state. The PassThrough node at n10962n cannot contain a child which does not appear under an iRegStore previously. It seems the iRegStores have been moved past the ificmpgt tree which is invalid as no treetop can appear after an ificmpx tree.

The symptom observed in all the above failures was that the following assembly was generated for this tree:

 [0x50DB393A00]   LGRL    &GPR_0705,0x0000000000000000
 [0x50DB393B10]   C       GPR_0672, Shadow[<array-shadow>] 16(&GPR_0705)
 [0x50DB393C60]   XR      GPR_0706,GPR_0706
 [0x50DB393F20]   LR      GPR_0707,GPR_0672   ; LR=Reg_deps2
 [0x50DB3945E0]   ASSOCREGS
  PRE:
 {GPR6:GPR_0706:R} {GPR7:GPR_0672:R} {GPR9:&GPR_0674:R} {GPR11:&GPR_0673:R} {GPR12:GPR_0707:R}
 [0x50DB394020]   BRC     BL(0x2), Label L0023
 POST:
 {GPR6:GPR_0706:R} {GPR7:GPR_0672:R} {GPR9:&GPR_0674:R} {GPR11:&GPR_0673:R} {GPR12:GPR_0707:R}

The XR overwrites the condition code of the C and so we never take the BRC branch. We'll need another few days to get a proper fix out but we are very close.

[JasonFengJ9]

[zOS S390] 80 JIT_Sanity.Daa.Mode101.1 failure from an internal acceptance build:

j> 19:09:25 20191029 19:09:25 <DAA|SimpleDriver|com.ibm.test.Arithmetics.TestArithmeticOperations.testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision|670|Default Invocant> ERROR: Test testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision(com.ibm.test.Arithmetics.TestArithmeticOperations) failed
j> 19:09:25 Throwable trace:
j> 19:09:25 testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision: arrays first differed at element [0]; expected:<80> but was:<0>
j> 19:09:25     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:52)
j> 19:09:25     at org.junit.Assert.internalArrayEquals(Assert.java:414)
j> 19:09:25     at org.junit.Assert.assertArrayEquals(Assert.java:200)
j> 19:09:25     at com.ibm.test.Arithmetics.TestArithmeticOperations.testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision(TestArithmeticOperations.java:14416)
j> 19:09:25     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
j> 19:09:25     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:90)
j> 19:09:25     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
j> 19:09:25     at java.lang.reflect.Method.invoke(Method.java:508)
j> 19:09:25     at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
j> 19:09:25     at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
j> 19:09:25     at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
j> 19:09:25     at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
j> 19:09:25     at org.junit.runners.BlockJUnit4ClassRunner.runNotIgnored(BlockJUnit4ClassRunner.java:79)
j> 19:09:25     at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:71)
j> 19:09:25     at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:49)
j> 19:09:25     at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
j> 19:09:25     at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
j> 19:09:25     at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
j> 19:09:25     at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
j> 19:09:25     at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
j> 19:09:25     at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
j> 19:09:25     at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
j> 19:09:25     at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
j> 19:09:25     at org.junit.runner.JUnitCore.run(JUnitCore.java:157)
j> 19:09:25     at org.junit.runner.JUnitCore.run(JUnitCore.java:136)
j> 19:09:25     at com.ibm.jtc.test.jltf.workunitadapters.JUnit4WorkUnit.runWork(JUnit4WorkUnit.java:300)
j> 19:09:25     at com.ibm.jtc.test.jltf.threads.WorkUnitRunner.run(WorkUnitRunner.java:113)
j> 19:09:25     at com.ibm.jtc.test.jltf.threads.pooling.PooledRunnable.runWork(PooledRunnable.java:170)
j> 19:09:25     at com.ibm.jtc.test.jltf.threads.pooling.PooledRunnable.getAndRunWork(PooledRunnable.java:136)
j> 19:09:25     at com.ibm.jtc.test.jltf.threads.pooling.PooledRunnable.run(PooledRunnable.java:93)
j> 19:09:25     at com.ibm.jtc.test.jltf.threads.PooledLangThreadFactory$JavaLangPooledThread.run(PooledLangThreadFactory.java:152)
j> 19:09:25 20191029 19:09:25 <DAA|SimpleDriver|com.ibm.test.Arithmetics.TestArithmeticOperations.testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision|670|Default Invocant> ERROR: JUnit test finished with: FAIL
j> 19:09:25 20191029 19:09:25 <DAA|SimpleDriver|com.ibm.test.Arithmetics.TestArithmeticOperations.testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision|670|Default Invocant> ERROR: Test testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision(com.ibm.test.Arithmetics.TestArithmeticOperations) failed: 

Does this appear another manifest of this issue?

[fjeremic]

Does this appear another manifest of this issue?

Yes this is the same issue.

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly/186
DaaLoadTest_daa1_0

00:17:38  DLT testStarted : testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance)
00:17:38  DLT java.lang.NumberFormatException: For input string: "21358160"
00:17:38  DLT   at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
00:17:38  DLT   at java.base/java.lang.Integer.parseInt(Integer.java:652)
00:17:38  DLT   at java.base/java.math.BigInteger.<init>(BigInteger.java:543)
00:17:38  DLT   at java.base/java.math.BigInteger.<init>(BigInteger.java:672)
00:17:38  DLT   at net.openj9.test.Utils.toPrecision(Utils.java:498)
00:17:38  DLT   at net.openj9.test.arithmetics.TestPerformance.getComparisionReferenceValue(TestPerformance.java:375)
00:17:38  DLT   at net.openj9.test.arithmetics.TestPerformance.testEQ(TestPerformance.java:273)
00:17:38  DLT   at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:86)

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly/187
DaaLoadTest_daa1_0

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Nightly/14
DaaLoadTest_daa1_special_22
variation: Mode687
JVM_OPTIONS: -Xcompressedrefs -XX:+UseCompressedOops -Xjit -Xgcpolicy:gencon -Xaggressiv

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Nightly/20
DaaLoadTest_daa1_special_20
variation: Mode610
JVM_OPTIONS: -Xcompressedrefs -Xcompressedrefs -Xjit -Xgcpolicy:gencon

[JasonFengJ9]

Segmentation error vmState=0x00020002 when running com.ibm.test.Arithmetics.TestPerformance

j> 21:59:52 Unhandled exception
j> 21:59:52 Type=Segmentation error vmState=0x00020002
j> 21:59:52 J9Generic_Signal_Number=00000018 Signal_Number=0000000b Error_Value=00000000 Signal_Code=00000080
j> 21:59:52 Handler1=00007F819E3540A0 Handler2=00007F819DC3A800 InaccessibleAddress=0000000000000000
j> 21:59:52 RDI=00007F8198047A00 RSI=0000000000000007 RAX=ABC5FFC223B6C800 RBX=00007F80D8B8DA88
j> 21:59:52 RCX=0000000000000000 RDX=0000000099669966 R8=00007F804800BCD8 R9=00007F80BE347760
j> 21:59:52 R10=000000000000BC16 R11=0000000000000005 R12=00007F819CC575C0 R13=00007F80940056B8
j> 21:59:52 R14=00007F80BE347470 R15=000000000000000C
j> 21:59:52 RIP=00007F819C8E8F19 GS=0000 FS=0000 RSP=00007F80BE347460
j> 21:59:52 EFlags=0000000000010246 CS=0033 RBP=00007F80BE347AE0 ERR=0000000000000000
j> 21:59:52 TRAPNO=000000000000000D OLDMASK=0000000000000000 CR2=0000000000000000
j> 21:59:52 xmm0 0000000300000003 (f: 3.000000, d: 6.365987e-314)
j> 21:59:52 xmm1 0000000300000000 (f: 0.000000, d: 6.365987e-314)
j> 21:59:52 xmm2 408f400000000000 (f: 0.000000, d: 1.000000e+03)
j> 21:59:52 xmm3 0000000000003795 (f: 14229.000000, d: 7.030060e-320)
j> 21:59:52 xmm4 0000000000003794 (f: 14228.000000, d: 7.029566e-320)
j> 21:59:52 xmm5 3ff2abfc30000000 (f: 805306368.000000, d: 1.166989e+00)
j> 21:59:52 xmm6 3feb6bc70b826709 (f: 193095440.000000, d: 8.569064e-01)
j> 21:59:52 xmm7 3bbcc86800000000 (f: 0.000000, d: 6.095003e-21)
j> 21:59:52 xmm8 402254a76e1c4f0e (f: 1847348992.000000, d: 9.165340e+00)
j> 21:59:52 xmm9 3ff0000000000000 (f: 0.000000, d: 1.000000e+00)
j> 21:59:52 xmm10 3ece800000000000 (f: 0.000000, d: 3.635883e-06)
j> 21:59:52 xmm11 3d6925b7281203d7 (f: 672269248.000000, d: 7.147300e-13)
j> 21:59:52 xmm12 3eca22b9b6f84a35 (f: 3069725184.000000, d: 3.115612e-06)
j> 21:59:52 xmm13 bbe1edd09737b561 (f: 2537010432.000000, d: -3.037285e-20)
j> 21:59:52 xmm14 402205966f2b4d80 (f: 1865108864.000000, d: 9.010913e+00)
j> 21:59:52 xmm15 0000000000000000 (f: 0.000000, d: 0.000000e+00)
j> 21:59:52 Module=/bluebird/builds/bld_431802/sdk/xa6480/jre/lib/amd64/default/libj9gc29.so
j> 21:59:52 Module_base_address=00007F819C782000
j> 21:59:52 Target=2_90_20191102_431802 (Linux 2.6.32-279.22.1.el6.x86_64)
j> 21:59:52 CPU=amd64 (4 logical CPUs) (0x1ec1dc000 RAM)
j> 21:59:52 ----------- Stack Backtrace -----------
j> 21:59:52 (0x00007F819C8E8F19 [libj9gc29.so+0x166f19])
j> 21:59:52 (0x00007F819756718F [libj9jit29.so+0x23318f])
j> 21:59:52 (0x00007F8197B820FF [libj9jit29.so+0x84e0ff])
j> 21:59:52 (0x00007F8197B8256C [libj9jit29.so+0x84e56c])
j> 21:59:52 (0x00007F8197B8331C [libj9jit29.so+0x84f31c])
j> 21:59:52 (0x00007F819E383B0E [libj9vm29.so+0xccb0e])
j> 21:59:52 (0x00007F819C7C1AD6 [libj9gc29.so+0x3fad6])
j> 21:59:52 (0x00007F819C7B61AD [libj9gc29.so+0x341ad])
j> 21:59:52 (0x00007F819C7B4EEF [libj9gc29.so+0x32eef])
j> 21:59:52 (0x00007F819C7B79D2 [libj9gc29.so+0x359d2])
j> 21:59:52 (0x00007F819C8E3B22 [libj9gc29.so+0x161b22])
j> 21:59:52 (0x00007F819C98C71D [libj9gc29.so+0x20a71d])
j> 21:59:52 (0x00007F819C8BDB6B [libj9gc29.so+0x13bb6b])
j> 21:59:52 (0x00007F819C8BD661 [libj9gc29.so+0x13b661])
j> 21:59:52 (0x00007F819DC3B563 [libj9prt29.so+0x22563])
j> 21:59:52 (0x00007F819C8BD1EC [libj9gc29.so+0x13b1ec])
j> 21:59:52 (0x00007F819E0AA326 [libj9thr29.so+0xe326])
j> 21:59:52 (0x0000003134E07AA1 [libpthread.so.0+0x7aa1])
j> 21:59:52 clone+0x6d (0x00000031346E893D [libc.so.6+0xe893d])
j> 21:59:52 ---------------------------------------
j> 21:59:52 JVMDUMP039I Processing dump event "gpf", detail "" at 2019/11/02 21:59:51 - please wait.
j> 21:59:52 JVMDUMP032I JVM requested System dump using '/tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/core.20191102.215951.7729.0001.dmp' in response to an event
p> 20191102-21:59:52 Dump /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/core.7977 spotted.
p> 20191102-21:59:52 Attempted to collect /proc/pid/maps and /proc/pid/smaps
p> 20191102-21:59:55 Dump /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/javacore.20191102.215951.7729.0002.txt spotted.
p> 20191102-21:59:55 Dump /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/Snap.20191102.215951.7729.0003.trc spotted.
p> 20191102-21:59:55 Dump /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/core.20191102.215951.7729.0001.dmp spotted.
p> 20191102-21:59:55 Attempted to collect /proc/pid/maps and /proc/pid/smaps
j> 21:59:55 JVMPORT030W /proc/sys/kernel/core_pattern setting "|/usr/libexec/abrt-hook-ccpp %s %c %p %u %g %t e" specifies that the core dump is to be piped to an external program.  Attempting to rename either core or core.7977.
j> 21:59:55 
j> 21:59:55 JVMDUMP010I System dump written to /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/core.20191102.215951.7729.0001.dmp
j> 21:59:55 JVMDUMP032I JVM requested Java dump using '/tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/javacore.20191102.215951.7729.0002.txt' in response to an event
j> 21:59:55 JVMDUMP010I Java dump written to /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/javacore.20191102.215951.7729.0002.txt
j> 21:59:55 JVMDUMP032I JVM requested Snap dump using '/tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/Snap.20191102.215951.7729.0003.trc' in response to an event
j> 21:59:55 JVMDUMP010I Snap dump written to /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/Snap.20191102.215951.7729.0003.trc
j> 21:59:55 JVMDUMP007I JVM Requesting JIT dump using '/tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/jitdump.20191102.215951.7729.0004.dmp'
j> 21:59:55 JVMDUMP010I JIT dump written to /tmp/bld_431802/daa.5mins/620048349/JLTF-daa-alone-mode101-20191102-2159/jitdump.20191102.215951.7729.0004.dmp
j> 21:59:55 JVMDUMP013I Processed dump event "gpf", detail "".
j> 21:59:55 00007F8074023800: Unhandled exception while validating object in stack frame in thread Pooled Thread #1 running com.ibm.test.Arithmetics.TestPerformance
j> 21:59:55 00007F8074023800:   O-Slot=00007F804800BCD8
j> 21:59:55 00007F8074023800:   O-Slot value=00007F80D8B8DA88
j> 21:59:55 00007F8074023800:   PC=00007F80C48CE28D
j> 21:59:55 00007F8074023800:   framesWalked=1
j> 21:59:55 00007F8074023800:   arg0EA=00007F804800BDD0
j> 21:59:55 00007F8074023800:   walkSP=00007F804800BB98
j> 21:59:55 00007F8074023800:   literals=0000000000000000
j> 21:59:55 00007F8074023800:   jitInfo=00007F80BE508CB8
j> 21:59:55 00007F8074023800:   method=00007F806C012AE8 (com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(I[BII[BII[BIIZ)V) (JIT)
j> 21:59:55 00007F8074023800:   stack=00007F8048005920-00007F804800C990
p> 20191102-21:59:55 Java Process completed. Total java component duration 45 seconds. Leaving process polling loop

[fjeremic]

@r30shah does your current fix address any of the above? We know at least several issues got fixed. Let's try to deliver that fix so the failures get less noisy and see what is left.

[pshipton]

@dmitripivkine pls see https://github.com/eclipse/openj9/issues/7275#issuecomment-549148379
This is a crash with a different vmstate 0x00020002 than we've seen before, but perhaps another dup of #7300

[r30shah]

@fjeremic Opened up the PR to fix couple of issues in https://github.com/eclipse/omr/pull/4535
The one mentioned by https://github.com/eclipse/openj9/issues/7275#issuecomment-549148379 is going to get fixed by this change.

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_extended.system_s390x_linux_Nightly/86
DaaLoadTest_all_0

[r30shah]

Update: I was able to find the bad method because of which we are seeing this failure.
The reason we fail is because when we call to get String from BigInteger in following code,
https://github.com/eclipse/openj9-systemtest/blob/6e6e2fe02409fdbd617dff730a4e6defd660eb09/openj9.test.daa/src/test.daa/net/openj9/test/Utils.java#L489
It returns bad string. Tracing down the path I found that method java/math/BigInteger.smallToString(I)Ljava/lang/String; is called which is compiled with profiling trees at very hot level, and that returns bad string. Also I have verified that this is the bad method with only enabling value profiling in this method and reproduced the failure.
Looking further to see If I can identify bad trees in the log (There are total 150 values being profiled).

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_sanity.system_s390x_linux_Nightly/87
DaaLoadTest_daa1_0

DLT testFailure: testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance): multiplyPackedDecimal: arrays first differed at element [6]; expected:<38> but was:<-16>
DLT multiplyPackedDecimal: arrays first differed at element [6]; expected:<38> but was:<-16>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Assert.java:341)
DLT     at net.openj9.test.arithmetics.TestPerformance.verify(TestPerformance.java:465)
DLT     at net.openj9.test.arithmetics.TestPerformance.testMul(TestPerformance.java:161)
DLT     at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:78)

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Nightly/38
DaaLoadTest_daa1_special_22
variation: Mode687
JVM_OPTIONS: -Xcompressedrefs -XX:+UseCompressedOops -Xjit -Xgcpolicy:gencon -Xaggressive

[dmitripivkine]

@dmitripivkine pls see #7275 (comment)
This is a crash with a different vmstate 0x00020002 than we've seen before, but perhaps another dup of #7300

This is duplicate of #7300

[r30shah]

Update: Found the issue. Issue happens because of the Post GRA block splitter and Here is the snippet from the method log which highlights the issue.

...
n1n nodeX
n2n    bloadi
...
Split Point
...
n3n nodeY
n2n   => bloadi

In case of above trees, when we split blocks after GRA optimization, it first tries to find a free register to store node n2n. Now in case it can not get any free register, it will create an auto slot to store the value. Now issue occurs because of the following piece of code, which stores the value to temp slot.

https://github.com/eclipse/omr/blob/fa59bff71bed30710551f33a9c653c4bbd35d99a/compiler/il/OMRBlock.cpp#L1498

Looking at the call of for opCodeForDirectStore
https://github.com/eclipse/openj9/blob/bcdabd73d29359586b2a2294f0c2b47eea9e1541/runtime/compiler/il/J9IL.cpp#L339-L351

In case of 8 bit or 16 Bit value, it will return istore . On Z platform, this was causing an issue if a subsequent byte load from that slot is stored into other memory slot then, it will try to use MVC instruction to copy character from memory to memory. This will load the most significant byte from the memory which will be zero, causing the failure mentioned in this issue.

I have a fix working and right now testing it with broader set of tests. Once testing is finished, will open up PR.
In my personal testing, I was able to reproduce failure mentioned in https://github.com/eclipse/openj9/issues/7299 as well and till now (I have run it 400x times manually - Without fix failure rate for issue mentioned in this PR was 1/30 and failure rate of the second issue (https://github.com/eclipse/openj9/issues/7299) was 1/00) I have not seen any failures.

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_s390x_linux_Nightly/671
DaaLoadTest_daa1_special_22

DLT testFailure: testMultiplyPackedDecimalTwoBigInteger(net.openj9.test.arithmetics.TestArithmeticOperations): testMultiplyPackedDecimalTwoBigInteger: arrays first differed at element [1]; expected:<80> but was:<0>
DLT testMultiplyPackedDecimalTwoBigInteger: arrays first differed at element [1]; expected:<80> but was:<0>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Assert.java:341)
DLT     at net.openj9.test.arithmetics.TestArithmeticOperations.testMultiplyPackedDecimalTwoBigInteger(TestArithmeticOperations.java:14359)

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_extended.system_s390x_linux_Nightly/194
DaaLoadTest_all_0 - NumberFormatException

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Nightly/68
DaaLoadTest_daa1_special_20 - NumberFormatException

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Personal/62
DaaLoadTest_daa1_special_22 - NumberFormatException
DaaLoadTest_daa1_special_20

[2019-11-10T10:55:25.728Z] DLT testFailure: testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance): remainderPackedDecimal: arrays first differed at element [9]; expected:<0> but was:<-48>
[2019-11-10T10:55:25.728Z] DLT remainderPackedDecimal: arrays first differed at element [9]; expected:<0> but was:<-48>
[2019-11-10T10:55:25.728Z] DLT  at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
[2019-11-10T10:55:25.728Z] DLT  at org.junit.Assert.internalArrayEquals(Assert.java:532)
[2019-11-10T10:55:25.728Z] DLT  at org.junit.Assert.assertArrayEquals(Assert.java:341)
[2019-11-10T10:55:25.728Z] DLT  at net.openj9.test.arithmetics.TestPerformance.verify(TestPerformance.java:465)
[2019-11-10T10:55:25.728Z] DLT  at net.openj9.test.arithmetics.TestPerformance.testRem(TestPerformance.java:202)
[2019-11-10T10:55:25.728Z] DLT  at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_s390x_linux_Nightly/683
DaaLoadTest_daa1_special_22

DLT testFailure: testIntrinsicPerformance(net.openj9.test.arithmetics.TestPerformance): multiplyPackedDecimal: arrays first differed at element [1]; expected:<85> but was:<0>
DLT multiplyPackedDecimal: arrays first differed at element [1]; expected:<85> but was:<0>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Assert.java:341)
DLT     at net.openj9.test.arithmetics.TestPerformance.verify(TestPerformance.java:465)
DLT     at net.openj9.test.arithmetics.TestPerformance.testMul(TestPerformance.java:161)
DLT     at net.openj9.test.arithmetics.TestPerformance.testIntrinsicPerformance(TestPerformance.java:78)

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly/198
DaaLoadTest_daa1_0 - NumberFormatException

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly/199
DaaLoadTest_daa1_0 - NumberFormatException

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Nightly/86
DaaLoadTest_daa2_special_22

[2019-11-12T11:44:28.359Z]         DLT testFailure: testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision(net.openj9.test.arithmetics.TestArithmeticOperations): testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision: arrays first differed at element [5]; expected:<35> but was:<-16>
[2019-11-12T11:44:28.360Z]         DLT testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision: arrays first differed at element [5]; expected:<35> but was:<-16>
[2019-11-12T11:44:28.360Z]         DLT  at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
[2019-11-12T11:44:28.360Z]         DLT  at org.junit.Assert.internalArrayEquals(Assert.java:532)
[2019-11-12T11:44:28.360Z]         DLT  at org.junit.Assert.assertArrayEquals(Assert.java:341)
[2019-11-12T11:44:28.360Z]         DLT  at net.openj9.test.arithmetics.TestArithmeticOperations.testMultiplyPackedDecimalTwoBigIntegeLossOfPrecision(TestArithmeticOperations.java:14424)

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_special.system_s390x_linux_Nightly/98
DaaLoadTest_daa2_special_22

DLT class net.openj9.test.PD2Primitive.TestI2PD Total: 10 Fail: 2 Ignore: 0
DLT     FAILURE: longPerformanceTest(net.openj9.test.PD2Primitive.TestI2PD) - arrays first differed at element [1]; expected:<-16> but was:<35>
DLT     FAILURE: randomTestLong(net.openj9.test.PD2Primitive.TestI2PD) - arrays first differed at element [1]; expected:<-48> but was:<2>

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk11_j9_sanity.system_s390x_linux_Nightly/205
DaaLoadTest_daa1_0 - NumberFormatException

https://ci.eclipse.org/openj9/job/Test_openjdk13_j9_extended.system_s390x_linux_Nightly/101
DaaLoadTest_all_0

 DLT class net.openj9.test.PD2Primitive.TestI2PD Total: 10 Fail: 2 Ignore: 0
 DLT    FAILURE: longPerformanceTest(net.openj9.test.PD2Primitive.TestI2PD) - For input string: "�2�3�2�36"
 DLT    FAILURE: randomTestLong(net.openj9.test.PD2Primitive.TestI2PD) - arrays first differed at element [1]; expected:<-48> but was:<83>

[pshipton]

https://ci.eclipse.org/openj9/job/Test_openjdk8_j9_special.system_s390x_linux_Nightly/731
DaaLoadTest_daa1_special_22

DLT testFailure: testMultiplyPackedDecimalTwoBigInteger(net.openj9.test.arithmetics.TestArithmeticOperations): testMultiplyPackedDecimalTwoBigInteger: arrays first differed at element [1]; expected:<80> but was:<0>
DLT testMultiplyPackedDecimalTwoBigInteger: arrays first differed at element [1]; expected:<80> but was:<0>
DLT     at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:55)
DLT     at org.junit.Assert.internalArrayEquals(Assert.java:532)
DLT     at org.junit.Assert.assertArrayEquals(Unknown Source)
DLT     at net.openj9.test.arithmetics.TestArithmeticOperations.testMultiplyPackedDecimalTwoBigInteger(TestArithmeticOperations.java:14359)

[fjeremic]

Looking forward to that OMR change propagating! Hopefully the UNB issues are resolved soon and we can get OMR-Acceptance builds running.

[fjeremic]

Looks like OMR finally promoted. Let's see if any similar issues pop up now with the fix in place. Hoping not! 🤞