openj9 icon indicating copy to clipboard operation
openj9 copied to clipboard

Published 20 hours ago • verified publisher icon eclipse-openj9

threadMXBeanTimedParkTest Blocked time is lower than expected

Open pshipton opened this issue 3 years ago • 23 comments

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_extended.functional_ppc64_aix_Nightly_testList_1/200 - p8-java1-ibm04 threadMXBeanTimedParkTest_0 -Xjit -Xgcpolicy:gencon -Xnocompressedrefs -Xthr:minimizeUserCPU

04:17:55  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
04:17:55  [TimedParkTest] [ERROR]   actual: 4426 expected: 5000 tolerance: 500
04:17:55  FAILED: testTimedParkTest
04:17:55  java.lang.AssertionError: The following asserts failed:
04:17:55  	expected [PASS] but found [FAIL]
04:17:55  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
04:17:55  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Feb 09 '22 12:02 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_extended.functional_ppc64_aix_Release_testList_0/4 - p8-java1-ibm03 threadMXBeanTimedParkTest_0 -Xjit -Xgcpolicy:gencon -Xnocompressedrefs -Xthr:minimizeUserCPU

15:41:51  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
15:41:51  [TimedParkTest] [ERROR]   actual: 4499 expected: 5000 tolerance: 500
15:41:51  FAILED: testTimedParkTest
15:41:51  java.lang.AssertionError: The following asserts failed:
15:41:51  	expected [PASS] but found [FAIL]
15:41:51  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
15:41:51  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Mar 21 '22 13:03 pshipton

There was an occurrence Mar 16 https://github.com/eclipse-openj9/openj9/issues/14728#issue-1170941745 copied here.

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_extended.functional_ppc64_aix_Nightly_testList_0/176 - p8-java1-ibm06 threadMXBeanTimedParkTest_3 -Xcompressedrefs -Xjit -Xgcpolicy:gencon -Xthr:minimizeUserCPU

00:35:47  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
00:35:47  [TimedParkTest] [ERROR]   actual: 4306 expected: 5000 tolerance: 500
00:35:47  FAILED: testTimedParkTest
00:35:47  java.lang.AssertionError: The following asserts failed:
00:35:47  	expected [PASS] but found [FAIL]
00:35:47  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
00:35:47  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Mar 22 '22 15:03 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_extended.functional_ppc64_aix_Nightly_testList_0/176 - p8-java1-ibm06 threadMXBeanTimedParkTest_3 - -Xcompressedrefs -Xjit -Xgcpolicy:gencon -Xthr:minimizeUserCPU

00:35:47  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
00:35:47  [TimedParkTest] [ERROR]   actual: 4306 expected: 5000 tolerance: 500
00:35:47  FAILED: testTimedParkTest
00:35:47  java.lang.AssertionError: The following asserts failed:
00:35:47  	expected [PASS] but found [FAIL]
00:35:47  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
00:35:47  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Mar 22 '22 15:03 pshipton

@tajila could there be an actual problem here? This only started occurring recently, and I was assuming a machine problem, but the actual times are lower not higher. All the failures are on AIX with -Xthr:minimizeUserCPU.

pshipton avatar Mar 22 '22 15:03 pshipton

I don't know this is vm so I'm tagging it as both vm and jit.

pshipton avatar Mar 22 '22 15:03 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_extended.functional_ppc64_aix_Nightly_testList_1/26/ - p8-java1-ibm07 threadMXBeanTimedParkTest_2 -Xgcpolicy:metronome -Xcompressedrefs -Xthr:minimizeUserCPU

03:16:08  [TimedParkTest] [ERROR] ERROR: Blocked time is higher than expected
03:16:08  [TimedParkTest] [ERROR]   actual: 8851 expected: 5000 tolerance: 2000
03:16:08  FAILED: testTimedParkTest
03:16:08  java.lang.AssertionError: The following asserts failed:
03:16:08  	expected [PASS] but found [FAIL]
03:16:08  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
03:16:08  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Mar 24 '22 12:03 pshipton

@mikezhang1234567890 Can you please take a look at this

tajila avatar Apr 05 '22 13:04 tajila

Looking into this, but haven't been able to reproduce the issue yet.

mikezhang1234567890 avatar Apr 05 '22 20:04 mikezhang1234567890

It was hot for a few day, but I haven't seen it since. If it can't be reproduced we can close it until it's seen again.

pshipton avatar Apr 06 '22 18:04 pshipton

@mikezhang1234567890 do you see anything about the test that would explain why the actual could be lower than the expected?

pshipton avatar Apr 06 '22 18:04 pshipton

I don't see anything in the test that would explain why it'd be lower.

I tried running in grinder with testNG verbose turned up: Ran 50x iterations of JDK18 internally at job/Grinder/22383/, no failures. Ran 50x iterations of JDK17 internally at job/Grinder/22384/, no failures. Ran 50x iterations of JDK11 at `job/Grinder/22388/, also no failures.

mikezhang1234567890 avatar Apr 06 '22 18:04 mikezhang1234567890

https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_extended.functional_ppc64_aix_Release_testList_0/9 threadMXBeanTimedParkTest_0

03:46:31  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
03:46:31  [TimedParkTest] [ERROR]   actual: 2455 expected: 5000 tolerance: 500
03:46:31  FAILED: testTimedParkTest
03:46:31  java.lang.AssertionError: The following asserts failed:
03:46:31  	expected [PASS] but found [FAIL]
03:46:31  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
03:46:31  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Apr 20 '22 14:04 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_extended.functional_ppc64_aix_Nightly_testList_1/208 threadMXBeanTimedParkTest_1

23:44:50  [TimedParkTest] [ERROR] ERROR: Blocked time is higher than expected
23:44:50  [TimedParkTest] [ERROR]   actual: 9083 expected: 5000 tolerance: 2000
23:44:54  FAILED: testTimedParkTest
23:44:54  java.lang.AssertionError: The following asserts failed:
23:44:54  	expected [PASS] but found [FAIL]
23:44:54  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
23:44:54  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_extended.functional_ppc64_aix_Nightly_testList_0/49 threadMXBeanTimedParkTest_1

03:23:50  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
03:23:50  [TimedParkTest] [ERROR]   actual: 3806 expected: 5000 tolerance: 500
03:23:50  FAILED: testTimedParkTest
03:23:50  java.lang.AssertionError: The following asserts failed:
03:23:50  	expected [PASS] but found [FAIL]
03:23:50  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
03:23:50  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Apr 29 '22 13:04 pshipton

@mikezhang1234567890 any progress on this?

tajila avatar May 09 '22 13:05 tajila

No, still haven't been able to reproduce the error with internal grinders.

mikezhang1234567890 avatar May 09 '22 13:05 mikezhang1234567890

https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_extended.functional_ppc64_aix_Nightly_testList_1/57

04:31:49  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
04:31:49  [TimedParkTest] [ERROR]   actual: 4407 expected: 5000 tolerance: 500
04:31:49  FAILED: testTimedParkTest
04:31:49  java.lang.AssertionError: The following asserts failed:
04:31:49  	expected [PASS] but found [FAIL]
04:31:49  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
04:31:49  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar May 11 '22 11:05 pshipton

@mikezhang1234567890 You can ask @AdamBrousseau to give you access to the external machines, seems to fail pretty frequently there

tajila avatar May 16 '22 18:05 tajila

https://openj9-jenkins.osuosl.org/job/Test_openjdk18_j9_extended.functional_ppc64_aix_Nightly_testList_0/72/

03:10:12  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
03:10:12  [TimedParkTest] [ERROR]   actual: 4060 expected: 5000 tolerance: 500
03:10:12  FAILED: testTimedParkTest
03:10:12  java.lang.AssertionError: The following asserts failed:
03:10:12  	expected [PASS] but found [FAIL]
03:10:12  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
03:10:12  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Jun 01 '22 13:06 pshipton

@mikezhang1234567890 were you able to make any progress on this?

tajila avatar Jun 07 '22 13:06 tajila

No, haven't managed to reproduce manually on the external machine https://openj9-jenkins.osuosl.org/computer/p8-java1-ibm09/

mikezhang1234567890 avatar Jun 07 '22 19:06 mikezhang1234567890

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_extended.functional_ppc64_aix_Nightly_testList_1/239 threadMXBeanTimedParkTest_1

23:50:48  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
23:50:48  [TimedParkTest] [ERROR]   actual: 3493 expected: 5000 tolerance: 500
23:50:48  FAILED: testTimedParkTest
23:50:48  java.lang.AssertionError: The following asserts failed:
23:50:48  	expected [PASS] but found [FAIL]
23:50:48  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
23:50:48  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Jun 10 '22 12:06 pshipton

We're not making much progress to resolve this, although it does occur every couple of weeks in the builds. Perhaps we can add some diagnostics into the VM so that when it does occur we get more information. In the meantime, I'm moving it to the Backlog.

pshipton avatar Jun 10 '22 14:06 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_extended.functional_ppc64_aix_Release_testList_0/30

17:49:58  [TimedParkTest] [ERROR]   actual: 4303 expected: 5000 tolerance: 500
17:49:59  FAILED: testTimedParkTest
17:49:59  java.lang.AssertionError: The following asserts failed:
17:49:59  	expected [PASS] but found [FAIL]
17:49:59  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
17:49:59  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Aug 03 '22 18:08 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_extended.functional_ppc64_aix_Nightly_testList_0/283

21:55:21  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
21:55:21  [TimedParkTest] [ERROR]   actual: 3944 expected: 5000 tolerance: 500
21:55:21  FAILED: testTimedParkTest
21:55:21  java.lang.AssertionError: The following asserts failed:
21:55:21  	expected [PASS] but found [FAIL]
21:55:21  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
21:55:21  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Aug 18 '22 19:08 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_extended.functional_ppc64_aix_Nightly_testList_0/60

06:25:21  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
06:25:21  [TimedParkTest] [ERROR]   actual: 4125 expected: 5000 tolerance: 500
06:25:21  FAILED: testTimedParkTest
06:25:21  java.lang.AssertionError: The following asserts failed:
06:25:21  	expected [PASS] but found [FAIL]
06:25:21  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
06:25:21  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Dec 13 '22 16:12 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_extended.functional_ppc64_aix_Nightly_testList_0/79 threadMXBeanTimedParkTest_0

05:24:49  [TimedParkTest] [ERROR] ERROR: Blocked time is lower than expected
05:24:49  [TimedParkTest] [ERROR]   actual: 4396 expected: 5000 tolerance: 500
05:24:49  FAILED: testTimedParkTest
05:24:49  java.lang.AssertionError: The following asserts failed:
05:24:49  	expected [PASS] but found [FAIL]
05:24:49  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
05:24:49  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

pshipton avatar Jan 09 '23 17:01 pshipton

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_extended.functional_ppc64_aix_Nightly_testList_1/119/consoleFull

02:39:31  ===============================================
02:39:31  Running test threadMXBeanTimedParkTest_0 ...
02:39:31  ===============================================
02:39:31  threadMXBeanTimedParkTest_0 Start Time: Fri Mar 10 07:35:31 2023 Epoch Time (ms): 1678433731692
02:39:31  variation: Mode110 -Xthr:minimizeUserCPU
02:39:31  JVM_OPTIONS:  -Xjit -Xgcpolicy:gencon -Xnocompressedrefs -Xthr:minimizeUserCPU 

02:40:19  [TimedParkTest] [ERROR] ERROR: Blocked time is higher than expected
02:40:19  [TimedParkTest] [ERROR]   actual: 9014 expected: 5000 tolerance: 2000
02:40:19  FAILED: testTimedParkTest
02:40:19  java.lang.AssertionError: The following asserts failed:
02:40:19  	expected [PASS] but found [FAIL]
02:40:19  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
02:40:19  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)
02:40:19  	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
02:40:19  	at java.base/java.lang.reflect.Method.invoke(Method.java:578)
02:40:19  	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:124)
02:40:19  	at org.testng.internal.Invoker.invokeMethod(Invoker.java:580)
02:40:19  	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:716)
02:40:19  	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:988)
02:40:19  	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
02:40:19  	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:109)
02:40:19  	at org.testng.TestRunner.privateRun(TestRunner.java:648)
02:40:19  	at org.testng.TestRunner.run(TestRunner.java:505)
02:40:19  	at org.testng.SuiteRunner.runTest(SuiteRunner.java:455)
02:40:19  	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:450)
02:40:19  	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:415)
02:40:19  	at org.testng.SuiteRunner.run(SuiteRunner.java:364)
02:40:19  	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
02:40:19  	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:84)
02:40:19  	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1208)
02:40:19  	at org.testng.TestNG.runSuitesLocally(TestNG.java:1137)
02:40:19  	at org.testng.TestNG.runSuites(TestNG.java:1049)
02:40:19  	at org.testng.TestNG.run(TestNG.java:1017)
02:40:19  	at org.testng.TestNG.privateMain(TestNG.java:1354)
02:40:19  	at org.testng.TestNG.main(TestNG.java:1323)
02:40:19  
02:40:19  
02:40:19  ===============================================
02:40:19      threadMXBeanTimedParkTest
02:40:19      Tests run: 1, Failures: 1, Skips: 0

JasonFengJ9 avatar Mar 10 '23 13:03 JasonFengJ9

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_extended.functional_ppc64_aix_Nightly_testList_0/517/consoleFull

23:14:52  [TimedParkTest] [ERROR] ERROR: Blocked time is higher than expected
23:14:52  [TimedParkTest] [ERROR]   actual: 7738 expected: 5000 tolerance: 2000
23:14:52  FAILED: testTimedParkTest
23:14:52  java.lang.AssertionError: The following asserts failed:
23:14:52  	expected [PASS] but found [FAIL]
23:14:52  	at org.testng.asserts.SoftAssert.assertAll(SoftAssert.java:43)
23:14:52  	at org.openj9.test.java.lang.management.ThreadMXBean.TimedParkTest.testTimedParkTest(TimedParkTest.java:200)

23:14:52  threadMXBeanTimedParkTest_0_FAILED

JasonFengJ9 avatar Jul 27 '23 17:07 JasonFengJ9