jit_tr_0 testNOPing expected:<?> but was:<B> #14469

pshipton · 2022-02-09T12:44:13Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_sanity.functional_ppc64_aix_Nightly_testList_1 - p8-java1-ibm06
jit_tr_0 -Xjit:noJitUntilMain -Xdump:java

03:01:47  FAILED: testNOPing
03:01:47  java.lang.AssertionError: expected:<?> but was:<B>
03:01:47  	at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
03:01:47  	at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364)
03:01:47  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80)
03:01:47  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:215)
03:01:47  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:222)
03:01:47  	at jit.test.tr.chtable.VirtualGuardTest.testNOPing(VirtualGuardTest.java:109)
03:01:47  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
03:01:47  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
03:01:47  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
03:01:47  	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
03:01:47  	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:124)
03:01:47  	at org.testng.internal.Invoker.invokeMethod(Invoker.java:580)
03:01:47  	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:716)
03:01:47  	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:988)
03:01:47  	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
03:01:47  	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:109)
03:01:47  	at org.testng.TestRunner.privateRun(TestRunner.java:648)
03:01:47  	at org.testng.TestRunner.run(TestRunner.java:505)
03:01:47  	at org.testng.SuiteRunner.runTest(SuiteRunner.java:455)
03:01:47  	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:450)
03:01:47  	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:415)
03:01:47  	at org.testng.SuiteRunner.run(SuiteRunner.java:364)
03:01:47  	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
03:01:47  	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:84)
03:01:47  	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1208)
03:01:47  	at org.testng.TestNG.runSuitesLocally(TestNG.java:1137)
03:01:47  	at org.testng.TestNG.runSuites(TestNG.java:1049)
03:01:47  	at org.testng.TestNG.run(TestNG.java:1017)
03:01:47  	at org.testng.TestNG.privateMain(TestNG.java:1354)
03:01:47  	at org.testng.TestNG.main(TestNG.java:1323)
03:01:47  
03:01:47  
03:01:47  ===============================================
03:01:47      chtableTest
03:01:47      Tests run: 7, Failures: 1, Skips: 0
03:01:47  ===============================================

@0xdaryl

The text was updated successfully, but these errors were encountered:

0xdaryl · 2022-02-09T13:29:24Z

@zl-wang : could you have someone triage this AIX failure please?

zl-wang · 2022-02-09T13:34:07Z

@IBMJimmyk help this investigation please

IBMJimmyk · 2022-02-14T04:16:36Z

The failing line in the failing test looks to be here:

openj9/test/functional/JIT_Test/src/jit/test/tr/chtable/VirtualGuardTest.java

Line 109 in c462b8b

AssertJUnit.assertEquals(result, 'B');

It seems like the problem is with checking the result. From the test output:

java.lang.AssertionError: expected:<?> but was:<B>

From the test source, the expected result is "B" and this actually matches the produced result. But, the "expected" result listed in the test is "?".

IBMJimmyk · 2022-02-15T19:42:50Z

The original failure didn't have any corefiles to work with so I tried to reproduce the problem. I did 200 runs via grinder and they all passed:

job/Grinder/20966/tapResults/
Passed 100/100

job/Grinder/20988/tapResults/
Passed 100/100

So there's not much I can do with this unless the problem shows up again.

pshipton · 2022-03-29T23:59:09Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk8_j9_sanity.functional_ppc64_aix_Nightly_testList_1/241 - p8-java1-ibm05
jit_tr_0 -Xjit:noJitUntilMain -Xdump:java

00:26:26  FAILED: testNOPing
00:26:26  java.lang.AssertionError: expected:<?> but was:<B>
00:26:26  	at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
00:26:26  	at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364)
00:26:26  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80)
00:26:26  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:215)
00:26:26  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:222)
00:26:26  	at jit.test.tr.chtable.VirtualGuardTest.testNOPing(VirtualGuardTest.java:109)

pshipton · 2022-04-04T14:18:55Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_ppc64_aix_Nightly_testList_0/190 - p8-java1-ibm11
jit_tr_0 -Xjit:noJitUntilMain -Xdump:java

22:25:52  FAILED: testNOPing
22:25:52  java.lang.AssertionError: expected:<?> but was:<B>
22:25:52  	at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
22:25:52  	at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364)
22:25:52  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80)
22:25:52  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:215)
22:25:52  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:222)
22:25:52  	at jit.test.tr.chtable.VirtualGuardTest.testNOPing(VirtualGuardTest.java:109)

JasonFengJ9 · 2022-04-05T22:10:22Z

job/Test_openjdk18_j9_sanity.functional_aarch64_mac_testList_2/16/(macaarch64rt2)

openjdk version "18-ea" 2022-03-22
IBM Semeru Runtime Open Edition 18.0.0.0-rc1a (build 18-ea+37)
Eclipse OpenJ9 VM 18.0.0.0-rc1a (build openj9-0.31.0-rc1a, JRE 18 Mac OS X aarch64-64-Bit 20220405_35 (JIT enabled, AOT enabled)
OpenJ9   - f9bde1a3b
OMR      - 582866494
JCL      - b4cac4a4ce4 based on jdk-18+37)

[2022-04-05T09:12:54.337Z] variation: -Xjit:noJitUntilMain -Xdump:java
[2022-04-05T09:12:54.337Z] JVM_OPTIONS:  -Xjit:noJitUntilMain -Xdump:java 

[2022-04-05T09:13:40.529Z] FAILED: testNOPing
[2022-04-05T09:13:40.529Z] java.lang.AssertionError: expected:<?> but was:<B>
[2022-04-05T09:13:40.529Z] 	at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
[2022-04-05T09:13:40.529Z] 	at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364)
[2022-04-05T09:13:40.529Z] 	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80)
[2022-04-05T09:13:40.529Z] 	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:215)
[2022-04-05T09:13:40.529Z] 	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:222)
[2022-04-05T09:13:40.529Z] 	at jit.test.tr.chtable.VirtualGuardTest.testNOPing(VirtualGuardTest.java:109)

[2022-04-05T09:14:16.855Z] ===============================================
[2022-04-05T09:14:16.855Z] JIT_Test suite
[2022-04-05T09:14:16.855Z] Total tests run: 16450, Failures: 1, Skips: 0
[2022-04-05T09:14:16.855Z] ===============================================
[2022-04-05T09:14:16.855Z] 
[2022-04-05T09:14:20.182Z] 
[2022-04-05T09:14:20.182Z] jit_tr_0_FAILED

pshipton · 2022-04-06T03:14:46Z

@zl-wang @IBMJimmyk the problem seems to be occurring quite frequently lately. Note the latest failure is on amac and not AIX like the original ones.

pshipton · 2023-09-05T18:20:23Z

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_ppc64_aix_OMR_testList_1/18
jit_tr_0

07:10:41  FAILED: testNOPing
07:10:41  java.lang.AssertionError: expected:<?> but was:<B>
07:10:41  	at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
07:10:41  	at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364)
07:10:41  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80)
07:10:41  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:215)
07:10:41  	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:222)
07:10:41  	at jit.test.tr.chtable.VirtualGuardTest.testNOPing(VirtualGuardTest.java:109)

zl-wang · 2023-09-05T18:23:59Z

@bhavanisn please take a look

pshipton · 2023-09-25T16:43:59Z

Internal build OMR acceptance - macaarch64rt5
jit_tr_0

FAILED: testNOPing
java.lang.AssertionError: expected:<?> but was:<B>
	at org.testng.AssertJUnit.fail(AssertJUnit.java:59)
	at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364)
	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80)
	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:215)
	at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:222)
	at jit.test.tr.chtable.VirtualGuardTest.testNOPing(VirtualGuardTest.java:109)

bhavanisn · 2023-09-29T02:34:04Z

Looks like the failure is not limited to ppc64_aix but could happen on other platforms too.

I tried to reproduce with Grinder runs, but is not reproducible.

The result calculated is ? whereas expected is B.

I analyzed the scenario where this can happen:

For the final result to be ? is very narrow as it has to be the last statement executed and the test case exited after that ie., keepOnGoing=false.
The possibility of state=? can happen only during the transition from class A to B. The assert in the default case verifies this intermediate result and sets state to ?. This is correct in normal scenarios as state=‘B’ in next iteration.
https://github.com/eclipse-openj9/openj9/blob/master/test/functional/JIT_Test/src/jit/test/tr/chtable/VirtualGuardTest.java#L72-L90

default:
   AssertJUnit.assertTrue("switching to ?", state == 'A' && result > 4*'A' && result < 4*'B');
   state = '?';

Class B is loaded after 6 secs and test case finishes at 10 secs when final task is executed. Unless there is a possibility that both task B and task FIN executed at same time, state=? cannot happen. In that case the question is why would task B start delayed by 4 secs.

// load B after 6 seconds			
timer.schedule(new NotifyTask(TASK_LOAD_B, this), SECONDS_6);
// schedule to be woken up after 10 seconds
timer.schedule(new NotifyTask(TASK_FIN, this), SECONDS_10);

As this failure is not reproducible, I would suggest if we can add some debug code in the test case so we can have more info to debug if it happens again.

pshipton added comp:jit test failure labels Feb 9, 2022

pshipton mentioned this issue Feb 9, 2022

(0.31.0) Replace forceUnresolvedDispatch() with isResolved*DispatchGuaranteed() #14463

Merged

bhavanisn mentioned this issue Oct 30, 2023

Log task start time to verify delays and modify the loop to skip intermediate state #18377

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

jit_tr_0 testNOPing expected:<?> but was:<B> #14469

jit_tr_0 testNOPing expected:<?> but was:<B> #14469

pshipton commented Feb 9, 2022

0xdaryl commented Feb 9, 2022

zl-wang commented Feb 9, 2022

IBMJimmyk commented Feb 14, 2022

IBMJimmyk commented Feb 15, 2022

pshipton commented Mar 29, 2022

pshipton commented Apr 4, 2022

JasonFengJ9 commented Apr 5, 2022

pshipton commented Apr 6, 2022

pshipton commented Sep 5, 2023

zl-wang commented Sep 5, 2023

pshipton commented Sep 25, 2023 •

edited

Loading

bhavanisn commented Sep 29, 2023

jit_tr_0 testNOPing expected:<?> but was:<B> #14469

jit_tr_0 testNOPing expected:<?> but was:<B> #14469

Comments

pshipton commented Feb 9, 2022

0xdaryl commented Feb 9, 2022

zl-wang commented Feb 9, 2022

IBMJimmyk commented Feb 14, 2022

IBMJimmyk commented Feb 15, 2022

pshipton commented Mar 29, 2022

pshipton commented Apr 4, 2022

JasonFengJ9 commented Apr 5, 2022

pshipton commented Apr 6, 2022

pshipton commented Sep 5, 2023

zl-wang commented Sep 5, 2023

pshipton commented Sep 25, 2023 • edited Loading

bhavanisn commented Sep 29, 2023

pshipton commented Sep 25, 2023 •

edited

Loading