Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DaaLoadTest_daa1 tests - **FAILED** Process DLT has hung #13477

Open
JasonFengJ9 opened this issue Sep 9, 2021 · 56 comments
Open

DaaLoadTest_daa1 tests - **FAILED** Process DLT has hung #13477

JasonFengJ9 opened this issue Sep 9, 2021 · 56 comments
Assignees
@hzongaro
Labels
bug comp:infra comp:jit prio:high test failure
Milestone
Backlog

Comments

@JasonFengJ9
Copy link
Member

Failure link

From an internal build Test_openjdk11_j9_special.system_ppc64le_linux_testList_2/111/ (ubu18le-rt1-4):

[2021-09-09T02:19:34.473Z] java version "11.0.13-beta" 2021-10-19
[2021-09-09T02:19:34.473Z] IBM Semeru Runtime Certified Edition 11.0.12.0 (build 11.0.13-beta+5-202109090107)
[2021-09-09T02:19:34.473Z] Eclipse OpenJ9 VM 11.0.12.0 (build master-92ccf02b2, JRE 11 Linux ppc64le-64-Bit Compressed References 20210908_164 (JIT enabled, AOT enabled)
[2021-09-09T02:19:34.473Z] OpenJ9   - 92ccf02b2
[2021-09-09T02:19:34.473Z] OMR      - 680b68120
[2021-09-09T02:19:34.473Z] JCL      - e851d14114 based on jdk-11.0.13+5)

Re-run the Grinder

Optional info

Failure output (captured from console output)

[2021-09-09T02:19:28.973Z] Running test DaaLoadTest_daa1_special_5m_4 ...
[2021-09-09T02:19:28.973Z] ===============================================
[2021-09-09T02:19:28.973Z] DaaLoadTest_daa1_special_5m_4 Start Time: Wed Sep  8 19:19:27 2021 Epoch Time (ms): 1631153967861
[2021-09-09T02:19:28.974Z] "/home/jenkins/workspace/Test_openjdk11_j9_special.system_ppc64le_linux_testList_2/openjdkbinary/j2sdk-image/bin/java" -Xshareclasses:destroyAll; "/home/jenkins/workspace/Test_openjdk11_j9_special.system_ppc64le_linux_testList_2/openjdkbinary/j2sdk-image/bin/java" -Xshareclasses:groupAccess,destroyAll; echo "cache cleanup done";
[2021-09-09T02:19:28.974Z] JVMSHRC005I No shared class caches available
[2021-09-09T02:19:28.974Z] JVMSHRC005I No shared class caches available
[2021-09-09T02:19:28.974Z] cache cleanup done
[2021-09-09T02:19:28.974Z] variation: Mode112
[2021-09-09T02:19:28.974Z] JVM_OPTIONS:  -Xgcpolicy:gencon -Xjit:count=0 -Xnocompressedrefs 

[2021-09-09T02:20:04.486Z] DLT 19:20:03.029 - Final test list:
[2021-09-09T02:20:04.486Z] DLT 19:20:03.129 -   0 ArbitraryJava[net.openj9.test.simple.ConvertDecimal invokeTest]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.130 -   1 ArbitraryJava[net.openj9.test.simple.MarshalUnmarshalBinary invokeTest]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.132 -   2 JUnit[net.openj9.test.arithmetics.TestArithmeticOperations]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.132 -   3 JUnit[net.openj9.test.arithmetics.TestArithmeticInline]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.132 -   4 JUnit[net.openj9.test.arithmetics.TestArithmetics]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.133 -   5 JUnit[net.openj9.test.arithmetics.TestComparisonEquals]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.133 -   6 JUnit[net.openj9.test.arithmetics.TestPDComparisons]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.133 -   7 JUnit[net.openj9.test.arithmetics.TestPerformance]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.133 -   8 JUnit[net.openj9.test.arithmetics.TestSubExceptions]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.133 -   9 JUnit[net.openj9.test.arithmetics.TestValidityChecking]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.133 -   10 JUnit[net.openj9.test.binaryData.LongIntegerComparison]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   11 JUnit[net.openj9.test.binaryData.TestOptimizer]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   12 JUnit[net.openj9.test.decimals.TestBD2PD2BD]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   13 JUnit[net.openj9.test.decimals.TestDecimalData]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   14 JUnit[net.openj9.test.decimals.TestDecimalData2]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   15 JUnit[net.openj9.test.PD2Primitive.TestPD2Primitives2PD]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   16 JUnit[net.openj9.test.PDMoveShifts.TestShiftsAndConvert]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   17 JUnit[net.openj9.test.PDMoveShifts.TestPDMove]  Weighting=1 
[2021-09-09T02:20:04.486Z] DLT 19:20:03.134 -   18 ArbitraryJava[net.openj9.test.PDMoveShifts.ShiftTestRunner invokeTest]  Weighting=1 
[2021-09-09T02:20:06.734Z] DLT 19:20:05.197 - Starting thread. Suite=0 thread=0
[2021-09-09T02:20:06.734Z] DLT 19:20:05.248 - Starting thread. Suite=0 thread=1
[2021-09-09T02:24:45.299Z] STF 19:24:33.408 - Heartbeat: Process DLT is still running
[2021-09-09T02:29:45.506Z] STF 19:29:33.130 - Heartbeat: Process DLT is still running
[2021-09-09T02:34:46.648Z] STF 19:34:33.380 - Heartbeat: Process DLT is still running
[2021-09-09T02:39:33.486Z] DLT 19:39:22.522 - Completed 100.0%. Number of tests started=2
[2021-09-09T02:39:33.486Z] DLT 19:39:22.523 - **POSSIBLE HANG DETECTED**
[2021-09-09T02:39:33.487Z] STF 19:39:22.601 - **FAILED** Process DLT has hung
[2021-09-09T02:39:33.487Z] STF 19:39:22.601 - Collecting dumps for: DLT
[2021-09-09T02:39:33.487Z] STF 19:39:22.601 - Sending SIG 3 to the java process to generate a javacore

[2021-09-09T02:40:55.178Z] STF 19:40:52.949 - =====================   R E S U L T S   =====================
[2021-09-09T02:40:55.178Z] STF 19:40:52.949 - Stage results:
[2021-09-09T02:40:55.178Z] STF 19:40:52.949 -   setUp:     pass
[2021-09-09T02:40:55.178Z] STF 19:40:52.949 -   execute:  *fail*
[2021-09-09T02:40:55.178Z] STF 19:40:52.949 -   teardown:  pass
[2021-09-09T02:40:55.178Z] STF 19:40:52.949 - 
[2021-09-09T02:40:55.178Z] STF 19:40:52.950 - Overall result: **FAILED**
[2021-09-09T02:40:55.178Z] 
[2021-09-09T02:40:55.178Z] DaaLoadTest_daa1_special_5m_4_FAILED
@JasonFengJ9
Copy link
Member Author

Also occurred at JDK17 M1 internal build Test_openjdk17_j9_special.system_ppc64le_linux_Personal/30/tapResults/

===============================================
Running test DaaLoadTest_daa1_special_5m_4 ...
===============================================
DaaLoadTest_daa1_special_5m_4 Start Time: Wed Sep  8 20:00:25 2021 Epoch Time (ms): 1631156425302
variation: Mode112
JVM_OPTIONS:  -Xgcpolicy:gencon -Xjit:count=0 -Xnocompressedrefs 

openjdk version "17-internal" 2021-09-14
OpenJDK Runtime Environment (build 17-internal+0-adhoc.jenkins.BuildJDK17ppc64lelinuxPersonal)
Eclipse OpenJ9 VM (build v0.28.0-release-139535d5a37, JRE 17 Linux ppc64le-64-Bit Compressed References 20210908_41 (JIT enabled, AOT enabled)
OpenJ9   - 139535d5a37
OMR      - 407eef0153b
JCL      - b6c1a570c77 based on jdk-17+35)

STF 20:15:29.047 - Heartbeat: Process DLT is still running
DLT 20:17:23.958 - Completed 100.0%. Number of tests started=6
DLT 20:17:52.863 - **POSSIBLE HANG DETECTED**
STF 20:17:54.339 - **FAILED** Process DLT has hung
STF 20:17:54.339 - Collecting dumps for: DLT
STF 20:17:54.339 - Sending SIG 3 to the java process to generate a javacore

STF 20:18:24.347 - Monitoring Report Summary:
STF 20:18:24.347 -   o Process DLT has hung
STF 20:18:24.348 - Killing processes: DLT
STF 20:18:24.348 -   o Process DLT pid 2606789 is not running
**FAILED** at step 1 (Run daa load test). Expected return value=0 Actual=1 at /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64le_linux_Personal_testList_2/aqa-tests/TKG/../TKG/output_16311564227809/DaaLoadTest_daa1_special_5m_4/20210908-200025-DaaLoadTest/execute.pl line 95.
STF 20:18:24.414 - **FAILED** execute script failed. Expected return value=0 Actual=1
STF 20:18:24.414 - 
STF 20:18:24.414 - ====================   T E A R D O W N   ====================
STF 20:18:24.414 - Running teardown: perl /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64le_linux_Personal_testList_2/aqa-tests/TKG/../TKG/output_16311564227809/DaaLoadTest_daa1_special_5m_4/20210908-200025-DaaLoadTest/tearDown.pl
STF 20:18:24.546 - TEARDOWN stage completed
STF 20:18:24.551 - 
STF 20:18:24.551 - =====================   R E S U L T S   =====================
STF 20:18:24.551 - Stage results:
STF 20:18:24.551 -   setUp:     pass
STF 20:18:24.551 -   execute:  *fail*
STF 20:18:24.551 -   teardown:  pass
STF 20:18:24.551 - 
STF 20:18:24.551 - Overall result: **FAILED**

DaaLoadTest_daa1_special_5m_4_FAILED

Since this occurred at JDK17, move it to 0.28.

@JasonFengJ9 JasonFengJ9 changed the title JDK11 ppc64le_linux DaaLoadTest_daa1_special_5m_4_FAILED - **FAILED** Process DLT has hung ppc64le_linux DaaLoadTest_daa1_special_5m_4_FAILED - **FAILED** Process DLT has hung Sep 9, 2021
@JasonFengJ9
Copy link
Member Author

JasonFengJ9 commented Sep 10, 2021 •
edited
Loading

Observed in JDK17 0.28 release build at job/Test_openjdk17_j9_special.system_ppc64le_linux_testList_2/55/

openjdk version "17-beta" 2021-09-14
IBM Semeru Runtime Open Edition 17.0.0.0-m1 (build 17-beta+35-202109100228)
Eclipse OpenJ9 VM 17.0.0.0-m1 (build openj9-0.28.0-m1, JRE 17 Linux ppc64le-64-Bit Compressed References 20210909_25 (JIT enabled, AOT enabled)
OpenJ9   - 5eef84fb1
OMR      - 0bf455f83
JCL      - b6c1a570c77 based on jdk-17+35)

[2021-09-10T04:04:43.907Z] STF 21:04:38.170 - Heartbeat: Process DLT is still running
[2021-09-10T04:06:13.501Z] DLT 21:06:04.490 - Completed 100.0%. Number of tests started=6
[2021-09-10T04:06:13.501Z] DLT 21:06:04.490 - **POSSIBLE HANG DETECTED**
[2021-09-10T04:06:13.501Z] DLT 21:06:04.620 - Completed 100.0%. Number of tests started=6 (+0)
[2021-09-10T04:06:13.501Z] DLT 21:06:04.720 - Completed 100.0%. Number of tests started=6 (+0)
[2021-09-10T04:06:13.501Z] DLT 21:06:04.821 - Completed 100.0%. Number of tests started=6 (+0)
[2021-09-10T04:06:13.501Z] STF 21:06:04.871 - **FAILED** Process DLT has hung

[2021-09-10T04:07:07.844Z] STF 21:07:04.886 - Monitoring Report Summary:
[2021-09-10T04:07:07.844Z] STF 21:07:04.886 -   o Process DLT has hung
[2021-09-10T04:07:07.844Z] STF 21:07:04.887 - Killing processes: DLT
[2021-09-10T04:07:07.844Z] STF 21:07:04.887 -   o Process DLT pid 24342 is not running
[2021-09-10T04:07:07.844Z] **FAILED** at step 1 (Run daa load test). Expected return value=0 Actual=1 at /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64le_linux_testList_2/aqa-tests/TKG/../TKG/output_16312451709116/DaaLoadTest_daa1_special_5m_4/20210909-203933-DaaLoadTest/execute.pl line 95.
[2021-09-10T04:07:07.844Z] STF 21:07:05.014 - **FAILED** execute script failed. Expected return value=0 Actual=1
[2021-09-10T04:07:07.844Z] STF 21:07:05.014 - 
[2021-09-10T04:07:07.844Z] STF 21:07:05.014 - ====================   T E A R D O W N   ====================
[2021-09-10T04:07:07.844Z] STF 21:07:05.014 - Running teardown: perl /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64le_linux_testList_2/aqa-tests/TKG/../TKG/output_16312451709116/DaaLoadTest_daa1_special_5m_4/20210909-203933-DaaLoadTest/tearDown.pl
[2021-09-10T04:07:07.844Z] STF 21:07:05.138 - TEARDOWN stage completed
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 - 
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 - =====================   R E S U L T S   =====================
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 - Stage results:
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 -   setUp:     pass
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 -   execute:  *fail*
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 -   teardown:  pass
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 - 
[2021-09-10T04:07:07.844Z] STF 21:07:05.143 - Overall result: **FAILED**
[2021-09-10T04:07:07.844Z] 
[2021-09-10T04:07:07.844Z] DaaLoadTest_daa1_special_5m_4_FAILED

Also observed at JDK11 job/Test_openjdk11_j9_special.system_ppc64le_linux_testList_4/112/

java version "11.0.13-beta" 2021-10-19
IBM Semeru Runtime Certified Edition 11.0.12.0 (build 11.0.13-beta+5-202109100106)
Eclipse OpenJ9 VM 11.0.12.0 (build master-a2a4729e4, JRE 11 Linux ppc64le-64-Bit Compressed References 20210909_165 (JIT enabled, AOT enabled)
OpenJ9   - a2a4729e4
OMR      - 680b68120
JCL      - e851d14114 based on jdk-11.0.13+5)

[2021-09-10T02:02:48.927Z] Running test DaaLoadTest_daa1_special_5m_1 ...
[2021-09-10T02:02:48.927Z] ===============================================

[2021-09-10T02:02:48.927Z] variation: Mode103
[2021-09-10T02:02:48.927Z] JVM_OPTIONS:  -Xgcpolicy:optthruput -Xjit:count=0 -Xnocompressedrefs 

[2021-09-10T02:23:04.159Z] STF 19:22:52.093 - Heartbeat: Process DLT is still running
[2021-09-10T02:26:08.468Z] DLT 19:26:02.258 - Completed 100.0%. Number of tests started=4
[2021-09-10T02:26:08.468Z] DLT 19:26:05.636 - **POSSIBLE HANG DETECTED**
[2021-09-10T02:26:08.468Z] STF 19:26:05.939 - **FAILED** Process DLT has hung
[2021-09-10T02:26:08.468Z] STF 19:26:05.939 - Collecting dumps for: DLT
[2021-09-10T02:26:08.468Z] STF 19:26:05.939 - Sending SIG 3 to the java process to generate a javacore

[2021-09-10T02:28:09.205Z] DaaLoadTest_daa1_special_5m_1_FAILED

Rerun in Grinder

job/Test_openjdk11_j9_special.system_ppc64le_linux_testList_1/113/

[2021-09-10T02:03:20.432Z] Running test DaaLoadTest_daa1_special_5m_6 ...
[2021-09-10T02:03:20.432Z] ===============================================

[2021-09-10T02:03:21.374Z] variation: Mode121
[2021-09-10T02:03:21.374Z] JVM_OPTIONS:  -Xgcpolicy:optavgpause -Xjit:count=0 -Xnocompressedrefs 

[2021-09-10T02:23:25.415Z] STF 19:23:24.088 - Heartbeat: Process DLT is still running
[2021-09-10T02:23:46.835Z] DLT 19:23:44.197 - Completed 100.0%. Number of tests started=3
[2021-09-10T02:23:46.835Z] DLT 19:23:44.197 - **POSSIBLE HANG DETECTED**
[2021-09-10T02:23:46.835Z] DLT 19:23:44.298 - Completed 100.0%. Number of tests started=3 (+0)
[2021-09-10T02:23:46.835Z] DLT 19:23:44.399 - Completed 100.0%. Number of tests started=3 (+0)
[2021-09-10T02:23:46.835Z] DLT 19:23:44.499 - Completed 100.0%. Number of tests started=3 (+0)
[2021-09-10T02:23:46.835Z] DLT 19:23:44.599 - Completed 100.0%. Number of tests started=3 (+0)
[2021-09-10T02:23:46.835Z] STF 19:23:44.635 - **FAILED** Process DLT has hung
[2021-09-10T02:23:46.835Z] STF 19:23:44.635 - Collecting dumps for: DLT
[2021-09-10T02:23:46.835Z] STF 19:23:44.635 - Sending SIG 3 to the java process to generate a javacore

[2021-09-10T02:24:45.337Z] DaaLoadTest_daa1_special_5m_6_FAILED

@JasonFengJ9
Copy link
Member Author

Observed at JDK11 aarch64_linux job/Test_openjdk11_j9_special.system_aarch64_linux_testList_3/73/

[2021-09-14T02:05:40.446Z] Running test DaaLoadTest_daa1_special_5m_23 ...
[2021-09-14T02:05:40.446Z] ===============================================
[2021-09-14T02:05:40.446Z] DaaLoadTest_daa1_special_5m_23 Start Time: Mon Sep 13 22:05:39 2021 Epoch Time (ms): 1631585139681
[2021-09-14T02:05:40.446Z] "/home/jenkins/workspace/Test_openjdk11_j9_special.system_aarch64_linux_testList_3/openjdkbinary/j2sdk-image/bin/java" -Xshareclasses:destroyAll; "/home/jenkins/workspace/Test_openjdk11_j9_special.system_aarch64_linux_testList_3/openjdkbinary/j2sdk-image/bin/java" -Xshareclasses:groupAccess,destroyAll; echo "cache cleanup done";
[2021-09-14T02:05:40.446Z] JVMSHRC005I No shared class caches available
[2021-09-14T02:05:40.446Z] JVMSHRC005I No shared class caches available
[2021-09-14T02:05:40.446Z] cache cleanup done
[2021-09-14T02:05:40.446Z] variation: Mode688
[2021-09-14T02:05:40.446Z] JVM_OPTIONS:  -Xcompressedrefs -Xjit:count=0 -Xgcpolicy:gencon -Xaggressive -Xconcurrentlevel0 

[2021-09-14T02:05:44.103Z] openjdk version "11.0.13-ea" 2021-10-19
[2021-09-14T02:05:44.103Z] IBM Semeru Runtime Open Edition 11.0.12.0 (build 11.0.13-ea+5)
[2021-09-14T02:05:44.103Z] Eclipse OpenJ9 VM 11.0.12.0 (build master-87c301e9d, JRE 11 Linux aarch64-64-Bit Compressed References 20210914_200 (JIT enabled, AOT enabled)
[2021-09-14T02:05:44.103Z] OpenJ9   - 87c301e9d
[2021-09-14T02:05:44.103Z] OMR      - 17c439ee7
[2021-09-14T02:05:44.103Z] JCL      - ddc29ca760 based on jdk-11.0.13+5)

[2021-09-14T02:25:56.527Z] STF 22:25:43.042 - Heartbeat: Process DLT is still running
[2021-09-14T02:30:19.709Z] DLT 22:30:17.223 - Completed 100.0%. Number of tests started=10
[2021-09-14T02:30:24.190Z] DLT 22:30:22.762 - **POSSIBLE HANG DETECTED**
[2021-09-14T02:30:24.190Z] DLT 22:30:22.764 - Thread completed. Suite=0 thread=5
[2021-09-14T02:30:24.190Z] STF 22:30:23.383 - **FAILED** Process DLT has hung

[2021-09-14T02:31:56.113Z] STF 22:31:53.613 - Overall result: **FAILED**
[2021-09-14T02:31:56.113Z] 
[2021-09-14T02:31:56.113Z] DaaLoadTest_daa1_special_5m_23_FAILED

@JasonFengJ9 JasonFengJ9 changed the title ppc64le_linux DaaLoadTest_daa1_special_5m_4_FAILED - **FAILED** Process DLT has hung DaaLoadTest_daa1_special_5m_4_FAILED - **FAILED** Process DLT has hung Sep 14, 2021
@JasonFengJ9
Copy link
Member Author

The message "Completed 100.0%. Number of tests started=10" in the console output suggests this might be a test issue.

As per STF Load Test Readme [1], Load test outputs periodic status reports. As well as showing progress these also prevent any outer test harness which treats output not being written to stdout as a hung test from doing so erroneously.
Load test outputs the string 'POSSIBLE HANG DETECTED' if no tests have completed within the previous 15 minutes. Before the process is terminated the diagnostics capture sequence described in 'java dumps' is triggered. If the test is being run on an IBM JVM this should result in 3 sets of java dumps, a core file, snap and jitdump files being created.

It appears that 100% tests have been completed and then determined hung after 15min, which doesn't seem a VM problem.
In addition, only javacore files were generated but no system cores.

@Mesbah-Alam @llxia any insights?

I think this is not a 0.28 stop-ship issue, moving to next release instead.

[1] https://github.com/adoptium/STF/blob/master/stf.load/docs/README.md

@llxia
Copy link
Contributor

llxia commented Sep 27, 2021

@Mesbah-Alam could you take a look into this? Thanks

@pshipton
Copy link
Member

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/8 - aix71-p8-6
DaaLoadTest_daa1_special_5m_20
-Xcompressedrefs -Xgcpolicy:gencon -Xjit:counts=- - - - - - 1 1 1 1000 250 250 - - - 10000 100000 10000,gcOnResolve,rtResolve,sampleInterval=2,scorchingSampleThreshold=10000,quickProfile -Xmn512k -Xcheck:gc:vmthreads:all:quiet

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/8/system_test_output.tar.gz

DLT 02:57:32.806 - Completed 47.4%. Number of tests started=111 (+11)
DLT 02:57:52.805 - Completed 54.1%. Number of tests started=116 (+5)
STF 02:59:48.043 - Heartbeat: Process DLT is still running
STF 03:04:48.230 - Heartbeat: Process DLT is still running
STF 03:09:48.143 - Heartbeat: Process DLT is still running
STF 03:14:48.392 - Heartbeat: Process DLT is still running
STF 03:19:48.229 - Heartbeat: Process DLT is still running
DLT 03:23:16.148 - Completed 100.0%. Number of tests started=119 (+3)
DLT 03:23:16.148 - **POSSIBLE HANG DETECTED**
DLT 03:23:16.283 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:16.403 - Completed 100.0%. Number of tests started=119 (+0)
STF 03:23:16.415 - **FAILED** Process DLT has hung
STF 03:23:16.415 - Collecting dumps for: DLT
STF 03:23:16.416 - Sending SIG 3 to the java process to generate a javacore
STF 03:23:16.418 - Running command: kill -3 19726554
STF 03:23:16.418 - Redirecting stderr to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_3.stderr
STF 03:23:16.418 - Redirecting stdout to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_3.stdout
STF 03:23:16.452 - Pausing for 30 seconds
STF 03:23:46.454 - Sending SIG 3 to the java process to generate a javacore
STF 03:23:46.465 - Running command: kill -3 19726554
STF 03:23:46.467 - Redirecting stderr to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_3.stderr
STF 03:23:46.467 - Redirecting stdout to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_3.stdout
STF 03:23:46.495 - Pausing for 30 seconds
STF 03:24:16.497 - Sending SIG 3 to the java process to generate a javacore
STF 03:24:16.511 - Running command: kill -3 19726554
STF 03:24:16.511 - Redirecting stderr to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_3.stderr
STF 03:24:16.511 - Redirecting stdout to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_3.stdout
STF 03:24:16.543 - Pausing for 30 seconds
STF 03:24:46.544 - Sending SIGABRT (kill -6) to the java process to generate a core
STF 03:24:46.549 - Running command: kill -6 19726554
STF 03:24:46.550 - Redirecting stderr to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_6.stderr
STF 03:24:46.550 - Redirecting stdout to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_6.stdout
STF 03:24:46.576 - Pausing for 30 seconds
STF 03:25:16.578 - Sending SIGXCPU (kill -24) to the java process to generate an OS dump
STF 03:25:16.579 - Running command: kill -24 19726554
STF 03:25:16.579 - Redirecting stderr to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_24.stderr
STF 03:25:16.579 - Redirecting stdout to /home/jenkins/workspace/Test_openjdk17_j9_special.system_ppc64_aix_Release_testList_2/aqa-tests/TKG/output_16344511419689/DaaLoadTest_daa1_special_5m_20/20211017-025427-DaaLoadTest/results/1.DLT.kill_24.stdout
DLT 03:23:16.788 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:16.943 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.069 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.173 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.275 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.376 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.488 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.601 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.713 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.827 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:17.938 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.039 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.148 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.250 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.353 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.456 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.563 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.688 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.790 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:18.895 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.017 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.130 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.234 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.340 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.441 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.543 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.648 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.813 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:19.918 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:20.021 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:20.365 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:20.468 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:20.576 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:20.683 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:20.786 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:20.889 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.023 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.131 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.242 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.360 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.491 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.600 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.709 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.824 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:21.925 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.029 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.137 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.239 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.347 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.455 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.561 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.671 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.773 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.878 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:22.720 - Thread completed. Suite=0 thread=0
DLT 03:23:22.979 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.087 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.223 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.333 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.446 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.555 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.663 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.764 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.881 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:23.986 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.098 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.210 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.319 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.428 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.534 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.642 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.751 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.867 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:24.971 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:32.840 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:23:52.797 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:24:12.753 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:24:32.757 - Completed 100.0%. Number of tests started=119 (+0)
DLT 03:24:40.179 - Thread completed. Suite=0 thread=3
DLT stderr JVMDUMP039I Processing dump event "user", detail "" at 2021/10/17 03:23:16 - please wait.

@hzongaro hzongaro mentioned this issue Oct 19, 2021
Closed
@hzongaro
Copy link
Member

hzongaro commented Nov 9, 2021

As described in issue #13726, in getCandidate, if the FlushCandidate has a known allocation candidate associated with it, that can be retrieved using FlushCandidate::getCandidate. However, if the FlushCandidate does not have an allocation candidate, getCandidate will iterate through all the allocation candidates.

The Java method that's being compiled - TestDecimalData2.testConvertBigDecimalNormals - has several hundred candidates for stack allocation, several hundred flush candidates, and well over 100000 nodes. For each node examined in TR_LocalFlushElimination::examineNode, it's iterating over the flush candidates, calling getCandidate, and for the several hundred flush candidates that have no associated candidate for stack allocation, it getCandidate is iterating over all the stack allocation candidates every time it is called. The compilation appears to be hanging, but in fact it's just taking a very long time, and can eventually complete.

Caching the fact that a FlushCandidate has no associated candidate for stack allocation appears to resolve the problem. Just testing out that change more thoroughly.

@hzongaro hzongaro mentioned this issue Nov 9, 2021
Merged
@hzongaro
Copy link
Member

hzongaro commented Nov 9, 2021

Fixed in pull request #13885

@JasonFengJ9
Copy link
Member Author

JDK19 milestone build 1(win16x64rt2-4)

openjdk version "19.0.2" 2023-01-17
IBM Semeru Runtime Open Edition 19.0.2.0-m1 (build 19.0.2+7)
Eclipse OpenJ9 VM 19.0.2.0-m1 (build v0.37.0-release-042864b42, JRE 19 Windows Server 2016 amd64-64-Bit Compressed References 20230117_56 (JIT enabled, AOT enabled)
OpenJ9   - 042864b42
OMR      - 79f110f00
JCL      - be7d0c27852 based on jdk-19.0.2+7)

[2023-03-02T23:49:04.204Z] variation: Mode107-OSRG
[2023-03-02T23:49:04.767Z] JVM_OPTIONS:  -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -

[2023-03-03T00:08:44.299Z] DLT 16:08:37.798 - Completed 100.0%. Number of tests started=139 (+0)
[2023-03-03T00:08:48.695Z] DLT 16:08:44.379 - **POSSIBLE HANG DETECTED**
[2023-03-03T00:08:48.695Z] STF 16:08:44.540 - **FAILED** Process DLT has hung
[2023-03-03T00:08:48.695Z] STF 16:08:44.540 - Collecting dumps for: DLT

[2023-03-03T00:10:24.767Z] STF 16:10:20.748 - Overall result: **FAILED**
[2023-03-03T00:10:24.767Z] -----------------------------------
[2023-03-03T00:10:24.767Z] DaaLoadTest_daa1_special_5m_24_FAILED

50x grinder

@pshipton
Copy link
Member

pshipton commented Mar 4, 2023

Failed 11/50

@0xdaryl
Copy link
Contributor

0xdaryl commented Mar 14, 2023

It is not clear how many unique problems we're seeing running this test. The last real investigation concluded there was a pathologically large JIT method causing the timeouts, however other failures reported in the past year seem to suggest there are other issues (though they could all be connected in some way).

This needs to be sorted out but it won't happen for 0.38. I'll at least commit to have someone look into the long JIT compilation in the coming months, but won't commit to a milestone just yet.

@pshipton
Copy link
Member

pshipton commented Mar 17, 2023 •
edited
Loading

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_2/6/ - win2019x64-openj9-5
DaaLoadTest_daa1_special_5m_24
-Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_2/6/system_test_output.tar.gz

12:09:12  DLT 11:09:08.393 - Completed 100.0%. Number of tests started=32 (+0)
12:09:18  DLT 11:09:17.362 - **POSSIBLE HANG DETECTED**
12:09:18  STF 11:09:17.772 - **FAILED** Process DLT has hung

2LKREGMON          Thread public flags mutex lock (0x000002233BCFCE08): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-1" (J9VMThread:0x00000000005A1900)

Running slowly or looping.

javacore 1

3XMTHREADINFO      "load-1" J9VMThread:0x00000000005A1900, omrthread_t:0x000002233BC88478, java/lang/Thread:0x0000000700574378, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x14, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700058030)
3XMTHREADINFO1            (native thread ID:0x1D0C, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1303.703125000 secs, user: 193.750000000 secs, system: 1109.953125000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=1319104 (0x1420C0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:541(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

javacore 3

3XMTHREADINFO      "load-1" J9VMThread:0x00000000005A1900, omrthread_t:0x000002233BC88478, java/lang/Thread:0x0000000700574378, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x14, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700058030)
3XMTHREADINFO1            (native thread ID:0x1D0C, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1318.421875000 secs, user: 195.281250000 secs, system: 1123.140625000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=212696 (0x33ED8)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

javacore 5

3XMTHREADINFO      "load-1" J9VMThread:0x00000000005A1900, omrthread_t:0x000002233BC88478, java/lang/Thread:0x0000000700574378, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x14, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700058030)
3XMTHREADINFO1            (native thread ID:0x1D0C, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1347.671875000 secs, user: 199.453125000 secs, system: 1148.218750000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=3372160 (0x337480)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/String.<init>(String.java:5317(Compiled Code))
4XESTACKTRACE                at java/lang/StringUTF16.newString(StringUTF16.java:1179(Compiled Code))
4XESTACKTRACE                at java/lang/String.substring(String.java:3489(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:549(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

@pshipton
Copy link
Member

pshipton commented Mar 17, 2023 •
edited
Loading

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_3/7 - win2019-x64-3
DaaLoadTest_all_special_5m_24

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_3/7/system_test_output.tar.gz

13:40:18  DLT 12:40:15.513 - Completed 100.0%. Number of tests started=85 (+0)
13:40:29  DLT 12:40:28.326 - **POSSIBLE HANG DETECTED**
13:40:29  STF 12:40:28.469 - **FAILED** Process DLT has hung

2LKREGMON          Thread public flags mutex lock (0x0000018CC95D75A8): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-1" (J9VMThread:0x00000000005C2F00)
2LKREGMON          &vmthread->threadNameMutex lock (0x0000018CC95D7658): <unowned>
2LKREGMON          Thread public flags mutex lock (0x0000018CC95D7708): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-2" (J9VMThread:0x00000000005C6B00)
2LKREGMON          &vmthread->threadNameMutex lock (0x0000018CC95D77B8): <unowned>
2LKREGMON          Thread public flags mutex lock (0x0000018CC95D7868): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-3" (J9VMThread:0x00000000005CA800)
2LKREGMON          Thread public flags mutex lock (0x0000018CC95D7B28): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-5" (J9VMThread:0x00000000005D2100)

javacore 2

3XMTHREADINFO      "load-1" J9VMThread:0x00000000005C2F00, omrthread_t:0x0000018CACF56D40, java/lang/Thread:0x00000007003D3788, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1C, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x21BC, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1322.718750000 secs, user: 42.375000000 secs, system: 1280.343750000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=478752 (0x74E20)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/String.<init>(String.java:5306)
4XESTACKTRACE                at java/lang/String.<init>(String.java:2088(Compiled Code))
4XESTACKTRACE                at java/lang/StringBuilder.toString(StringBuilder.java:453(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80(Compiled Code))

3XMTHREADINFO      "load-2" J9VMThread:0x00000000005C6B00, omrthread_t:0x0000018CACF57208, java/lang/Thread:0x00000007003D3180, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1D, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x688, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1319.421875000 secs, user: 78.921875000 secs, system: 1240.500000000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=579432 (0x8D768)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/String.<init>(String.java:5292)
4XESTACKTRACE                at java/lang/String.<init>(String.java:2088(Compiled Code))
4XESTACKTRACE                at java/lang/StringBuilder.toString(StringBuilder.java:453(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80(Compiled Code))

3XMTHREADINFO      "load-3" J9VMThread:0x00000000005CA800, omrthread_t:0x0000018CACF576D0, java/lang/Thread:0x00000007003D2EE0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1E, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x1868, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1320.125000000 secs, user: 78.234375000 secs, system: 1241.890625000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=530272 (0x81760)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:550(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:924(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80(Compiled Code))

3XMTHREADINFO      "load-5" J9VMThread:0x00000000005D2100, omrthread_t:0x0000018CCABA2368, java/lang/Thread:0x00000007003EF460, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x20, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x1938, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1325.265625000 secs, user: 89.546875000 secs, system: 1235.718750000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=568376 (0x8AC38)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:514(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:924(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

javacore 4

3XMTHREADINFO      "load-1" J9VMThread:0x00000000005C2F00, omrthread_t:0x0000018CACF56D40, java/lang/Thread:0x00000007003D3788, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1C, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x21BC, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1352.531250000 secs, user: 43.406250000 secs, system: 1309.125000000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=196384 (0x2FF20)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:550(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80(Compiled Code))

3XMTHREADINFO      "load-2" J9VMThread:0x00000000005C6B00, omrthread_t:0x0000018CACF57208, java/lang/Thread:0x00000007003D3180, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1D, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x688, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1349.187500000 secs, user: 80.390625000 secs, system: 1268.796875000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=195248 (0x2FAB0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/StringBuilder.toString(StringBuilder.java:453(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.toString(BigInteger.java:4102(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.toString(BigInteger.java:4274(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.putBigInteger(PackedDecimal.java:837(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:946(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80(Compiled Code))

3XMTHREADINFO      "load-3" J9VMThread:0x00000000005CA800, omrthread_t:0x0000018CACF576D0, java/lang/Thread:0x00000007003D2EE0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x1E, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x1868, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1349.859375000 secs, user: 79.453125000 secs, system: 1270.406250000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=173488 (0x2A5B0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:541(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80(Compiled Code))

3XMTHREADINFO      "load-5" J9VMThread:0x00000000005D2100, omrthread_t:0x0000018CCABA2368, java/lang/Thread:0x00000007003EF460, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x20, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007001410B8)
3XMTHREADINFO1            (native thread ID:0x1938, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1355.015625000 secs, user: 91.375000000 secs, system: 1263.640625000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=2685480 (0x28FA28)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/invoke/LambdaForm$MH/0x00000000ca9dd730.invokeExact_MT(LambdaForm$MH(Compiled Code))
4XESTACKTRACE                at jdk/internal/reflect/DirectMethodHandleAccessor.invokeImpl(DirectMethodHandleAccessor.java:155)
4XESTACKTRACE                at jdk/internal/reflect/DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104(Compiled Code))
4XESTACKTRACE                at java/lang/reflect/Method.invoke(Method.java:578(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.getComparisionReferenceValue(TestPerformance.java:380(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testEQ(TestPerformance.java:273)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:86)

@pshipton
Copy link
Member

pshipton commented Mar 17, 2023 •
edited
Loading

https://openj9-jenkins.osuosl.org/job/Test_openjdk11_j9_special.system_x86-64_windows_Release_testList_2/49 - win2019x64-openj9-1
DaaLoadTest_daa1_special_5m_24

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk11_j9_special.system_x86-64_windows_Release_testList_2/49/system_test_output.tar.gz

00:59:59  DLT 23:59:55.693 - Completed 100.0%. Number of tests started=87 (+0)
01:00:09  DLT 00:00:07.708 - **POSSIBLE HANG DETECTED**
01:00:09  STF 00:00:07.977 - **FAILED** Process DLT has hung

2LKREGMON          Thread public flags mutex lock (0x000002074D8D71F8): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-0" (J9VMThread:0x00000000003A0B00)
2LKREGMON          Thread public flags mutex lock (0x000002074D8D74B8): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-1" (J9VMThread:0x00000000004FFD00)

Seems to be running slowly or looping.

javacore 2

3XMTHREADINFO      "load-0" J9VMThread:0x00000000003A0B00, omrthread_t:0x000002074D810F30, java/lang/Thread:0x00000007003A5CF0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x12, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700053920)
3XMTHREADINFO1            (native thread ID:0xB38, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1127.718750000 secs, user: 172.656250000 secs, system: 955.062500000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=163576 (0x27EF8)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/util/regex/Pattern$GroupHead.match(Pattern.java:4807)
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BranchConn.match(Pattern.java:4716)
4XESTACKTRACE                at java/util/regex/Pattern$GroupTail.match(Pattern.java:4866(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$GroupHead.match(Pattern.java:4807)
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4752(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharProperty.match(Pattern.java:3967)
4XESTACKTRACE                at java/util/regex/Pattern$Start.match(Pattern.java:3622(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.search(Matcher.java:1729(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.find(Matcher.java:773(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.parse(Formatter.java:2702(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2655(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2609(Compiled Code))
4XESTACKTRACE                at java/lang/String.format(String.java:3728(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRight(TestShiftsAndConvert.java:3325(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRightSimpleRound(TestShiftsAndConvert.java:3394(Compiled Code))

3XMTHREADINFO      "load-1" J9VMThread:0x00000000004FFD00, omrthread_t:0x000002074D8113F8, java/lang/Thread:0x00000007003A6080, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700053920)
3XMTHREADINFO1            (native thread ID:0x1BB8, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1120.531250000 secs, user: 176.328125000 secs, system: 944.203125000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=147136 (0x23EC0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/util/regex/Pattern$BranchConn.match(Pattern.java:4716)
4XESTACKTRACE                at java/util/regex/Pattern$GroupTail.match(Pattern.java:4866(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$GroupHead.match(Pattern.java:4807)
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4752(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharProperty.match(Pattern.java:3967)
4XESTACKTRACE                at java/util/regex/Pattern$Start.match(Pattern.java:3622(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.search(Matcher.java:1729(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.find(Matcher.java:773(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.parse(Formatter.java:2702(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2655(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2609(Compiled Code))
4XESTACKTRACE                at java/lang/String.format(String.java:3728(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftLeft(TestShiftsAndConvert.java:2478(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftLeftSimpleRandom(TestShiftsAndConvert.java:2426(Compiled Code))

javacore 3

3XMTHREADINFO      "load-0" J9VMThread:0x00000000003A0B00, omrthread_t:0x000002074D810F30, java/lang/Thread:0x00000007003A5CF0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x12, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700053920)
3XMTHREADINFO1            (native thread ID:0xB38, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1136.515625000 secs, user: 173.875000000 secs, system: 962.640625000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=168344 (0x29198)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharProperty.match(Pattern.java:3966)
4XESTACKTRACE                at java/util/regex/Pattern$Start.match(Pattern.java:3622(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.search(Matcher.java:1729(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.find(Matcher.java:773(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.parse(Formatter.java:2702(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2655(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2609(Compiled Code))
4XESTACKTRACE                at java/lang/String.format(String.java:3728(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRight(TestShiftsAndConvert.java:3325(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRightLowerDstPrec(TestShiftsAndConvert.java:3360(Compiled Code))

3XMTHREADINFO      "load-1" J9VMThread:0x00000000004FFD00, omrthread_t:0x000002074D8113F8, java/lang/Thread:0x00000007003A6080, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700053920)
3XMTHREADINFO1            (native thread ID:0x1BB8, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1129.390625000 secs, user: 177.640625000 secs, system: 951.750000000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=159680 (0x26FC0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/util/regex/Pattern$GroupHead.match(Pattern.java:4807)
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BranchConn.match(Pattern.java:4716)
4XESTACKTRACE                at java/util/regex/Pattern$GroupTail.match(Pattern.java:4866(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$GroupHead.match(Pattern.java:4807)
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4752(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharProperty.match(Pattern.java:3967)
4XESTACKTRACE                at java/util/regex/Pattern$Start.match(Pattern.java:3622(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.search(Matcher.java:1729(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.find(Matcher.java:773(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.parse(Formatter.java:2702(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2655(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2609(Compiled Code))
4XESTACKTRACE                at java/lang/String.format(String.java:3728(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftLeft(TestShiftsAndConvert.java:2478(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftLeftSimpleRandom(TestShiftsAndConvert.java:2426(Compiled Code))

javacore 5

3XMTHREADINFO      "load-0" J9VMThread:0x00000000003A0B00, omrthread_t:0x000002074D810F30, java/lang/Thread:0x00000007003A5CF0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x12, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700053920)
3XMTHREADINFO1            (native thread ID:0xB38, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1165.625000000 secs, user: 177.875000000 secs, system: 987.750000000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=3646040 (0x37A258)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharProperty.match(Pattern.java:3966)
4XESTACKTRACE                at java/util/regex/Pattern$Start.match(Pattern.java:3622(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.search(Matcher.java:1729(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.find(Matcher.java:773(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.parse(Formatter.java:2702(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2655(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2609(Compiled Code))
4XESTACKTRACE                at java/lang/String.format(String.java:3728(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRight(TestShiftsAndConvert.java:3325(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRightSimple(TestShiftsAndConvert.java:3342(Compiled Code))

3XMTHREADINFO      "load-1" J9VMThread:0x00000000004FFD00, omrthread_t:0x000002074D8113F8, java/lang/Thread:0x00000007003A6080, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700053920)
3XMTHREADINFO1            (native thread ID:0x1BB8, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1158.500000000 secs, user: 181.593750000 secs, system: 976.906250000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=3613072 (0x372190)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharProperty.match(Pattern.java:3967)
4XESTACKTRACE                at java/util/regex/Pattern$GroupHead.match(Pattern.java:4807)
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BranchConn.match(Pattern.java:4716)
4XESTACKTRACE                at java/util/regex/Pattern$GroupTail.match(Pattern.java:4866(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$GroupHead.match(Pattern.java:4807)
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4752(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$Branch.match(Pattern.java:4750(Compiled Code))
4XESTACKTRACE                at java/util/regex/Pattern$BmpCharProperty.match(Pattern.java:3967)
4XESTACKTRACE                at java/util/regex/Pattern$Start.match(Pattern.java:3622(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.search(Matcher.java:1729(Compiled Code))
4XESTACKTRACE                at java/util/regex/Matcher.find(Matcher.java:773(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.parse(Formatter.java:2702(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2655(Compiled Code))
4XESTACKTRACE                at java/util/Formatter.format(Formatter.java:2609(Compiled Code))
4XESTACKTRACE                at java/lang/String.format(String.java:3728(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRight(TestShiftsAndConvert.java:3325(Compiled Code))
4XESTACKTRACE                at net/openj9/test/PDMoveShifts/TestShiftsAndConvert.testShiftRightSimpleRound(TestShiftsAndConvert.java:3394(Compiled Code))

@pshipton
Copy link
Member

pshipton commented Mar 20, 2023 •
edited
Loading

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_3/8 - win2019x64-openj9-4
DaaLoadTest_all_special_5m_24
-Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_3/8/system_test_output.tar.gz

19:40:05  DLT 19:40:04.412 - Completed 100.0%. Number of tests started=53 (+0)
19:40:26  DLT 19:40:23.772 - **POSSIBLE HANG DETECTED**
19:40:26  STF 19:40:23.790 - **FAILED** Process DLT has hung

2LKREGMON          Thread public flags mutex lock (0x000001FDC9D467E8): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-0" (J9VMThread:0x0000000000400100)

Seems to be running slowly or looping.

javacore 2

3XMTHREADINFO      "load-0" J9VMThread:0x0000000000400100, omrthread_t:0x000001FDC9CDF880, java/lang/Thread:0x0000000700300330, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700051060)
3XMTHREADINFO1            (native thread ID:0x1398, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1187.500000000 secs, user: 179.546875000 secs, system: 1007.953125000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=165752 (0x28778)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/math/BigInteger.remainderKnuth(BigInteger.java:2492(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.remainder(BigInteger.java:2483(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:942(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

javacore 4

3XMTHREADINFO      "load-0" J9VMThread:0x0000000000400100, omrthread_t:0x000001FDC9CDF880, java/lang/Thread:0x0000000700300330, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700051060)
3XMTHREADINFO1            (native thread ID:0x1398, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1201.812500000 secs, user: 181.328125000 secs, system: 1020.484375000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=53208 (0xCFD8)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:195)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

javacore 6

3XMTHREADINFO      "load-0" J9VMThread:0x0000000000400100, omrthread_t:0x000001FDC9CDF880, java/lang/Thread:0x0000000700300330, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x0000000700051060)
3XMTHREADINFO1            (native thread ID:0x1398, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 1229.468750000 secs, user: 185.859375000 secs, system: 1043.609375000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=196904 (0x30128)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:541(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:924(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal_(PackedDecimal.java:810(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.remainderPackedDecimal(PackedDecimal.java:803)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testRem(TestPerformance.java:197)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:80)

@pshipton
Copy link
Member

Seems to me the win2019 machines are slower than the older win2012 machines. I wonder if the test just times out too quickly for these machines.

@pshipton
Copy link
Member

https://openj9-jenkins.osuosl.org/job/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_3/9 - win2019x64-openj9-4/9/system_test_output.tar.gz
DaaLoadTest_all_special_5m_24

https://openj9-artifactory.osuosl.org/artifactory/ci-openj9/Test/Test_openjdk19_j9_special.system_x86-64_windows_Personal_testList_3/9/system_test_output.tar.gz

17:57:56  DLT 17:57:52.344 - Completed 100.0%. Number of tests started=2 (+0)
17:57:56  DLT 17:57:52.782 - **POSSIBLE HANG DETECTED**
17:57:56  STF 17:57:53.252 - **FAILED** Process DLT has hung

javacore 2

2LKREGMON          Thread public flags mutex lock (0x00000146BC12DC68): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-0" (J9VMThread:0x0000000000400100)

2LKREGMON          Thread public flags mutex lock (0x00000146BC12DFD8): <unowned>
3LKNOTIFYQ            Waiting to be notified:
3LKWAITNOTIFY            "load-1" (J9VMThread:0x000000000059B400)

3XMTHREADINFO      "load-0" J9VMThread:0x0000000000400100, omrthread_t:0x00000146BC0370F0, java/lang/Thread:0x00000007006B6BB0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007000510F0)
3XMTHREADINFO1            (native thread ID:0x1008, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 904.234375000 secs, user: 117.187500000 secs, system: 787.046875000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=455376 (0x6F2D0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:541(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal_(PackedDecimal.java:741(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal(PackedDecimal.java:733)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testDiv(TestPerformance.java:176)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:79)

3XMTHREADINFO      "load-1" J9VMThread:0x000000000059B400, omrthread_t:0x00000146BC0375B8, java/lang/Thread:0x00000007006B6FF8, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x14, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007000510F0)
3XMTHREADINFO1            (native thread ID:0x668, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 904.171875000 secs, user: 120.171875000 secs, system: 784.000000000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=419680 (0x66760)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:672(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:550(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:924(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal_(PackedDecimal.java:741(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal(PackedDecimal.java:733)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testDiv(TestPerformance.java:176(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:79(Compiled Code))

javacore 3

3XMTHREADINFO      "load-0" J9VMThread:0x0000000000400100, omrthread_t:0x00000146BC0370F0, java/lang/Thread:0x00000007006B6BB0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007000510F0)
3XMTHREADINFO1            (native thread ID:0x1008, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000001)
3XMCPUTIME               CPU usage total: 913.609375000 secs, user: 118.359375000 secs, system: 795.250000000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=2164336 (0x210670)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:541(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:922(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal_(PackedDecimal.java:741(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal(PackedDecimal.java:733)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testDiv(TestPerformance.java:176)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:79)

3XMTHREADINFO      "load-1" J9VMThread:0x000000000059B400, omrthread_t:0x00000146BC0375B8, java/lang/Thread:0x00000007006B6FF8, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x14, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007000510F0)
3XMTHREADINFO1            (native thread ID:0x668, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000001)
3XMCPUTIME               CPU usage total: 913.453125000 secs, user: 121.265625000 secs, system: 792.187500000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=2118184 (0x205228)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:550(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:924(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal_(PackedDecimal.java:741(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal(PackedDecimal.java:733)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testDiv(TestPerformance.java:176(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:79(Compiled Code))

javacore 6

3XMTHREADINFO      "load-0" J9VMThread:0x0000000000400100, omrthread_t:0x00000146BC0370F0, java/lang/Thread:0x00000007006B6BB0, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x13, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007000510F0)
3XMTHREADINFO1            (native thread ID:0x1008, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 943.437500000 secs, user: 121.859375000 secs, system: 821.578125000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=130288 (0x1FCF0)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10935)
4XESTACKTRACE                at java/lang/Character.digit(Character.java:10883(Compiled Code))
4XESTACKTRACE                at java/lang/Integer.parseInt(Integer.java:663(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:541(Compiled Code))
4XESTACKTRACE                at java/math/BigInteger.<init>(BigInteger.java:679(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.getBigInteger(PackedDecimal.java:828(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:924(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal_(PackedDecimal.java:741(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal(PackedDecimal.java:733)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testDiv(TestPerformance.java:176)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:79)

3XMTHREADINFO      "load-1" J9VMThread:0x000000000059B400, omrthread_t:0x00000146BC0375B8, java/lang/Thread:0x00000007006B6FF8, state:R, prio=5
3XMJAVALTHREAD            (java/lang/Thread getId:0x14, isDaemon:false)
3XMJAVALTHRCCL            jdk/internal/loader/ClassLoaders$AppClassLoader(0x00000007000510F0)
3XMTHREADINFO1            (native thread ID:0x668, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081)
3XMCPUTIME               CPU usage total: 943.359375000 secs, user: 125.343750000 secs, system: 818.015625000 secs, current category="Application"
3XMHEAPALLOC             Heap bytes allocated since last GC cycle=118048 (0x1CD20)
3XMTHREADINFO3           Java callstack:
4XESTACKTRACE                at java/math/BigInteger.divide(BigInteger.java:2417(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.packedDecimalBinaryOp(PackedDecimal.java:939(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal_(PackedDecimal.java:741(Compiled Code))
4XESTACKTRACE                at com/ibm/dataaccess/PackedDecimal.dividePackedDecimal(PackedDecimal.java:733)
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testDiv(TestPerformance.java:176(Compiled Code))
4XESTACKTRACE                at net/openj9/test/arithmetics/TestPerformance.testIntrinsicPerformance(TestPerformance.java:79(Compiled Code))

@pshipton
Copy link
Member

pshipton commented Mar 27, 2023 •
edited
Loading

Seems to me the win2019 machines are slower than the older win2012 machines. I wonder if the test just times out too quickly for these machines.

I'm going to start ignoring failures that match this pattern, hang on win2019 machines.
DaaLoadTest_all_special_5m_24
DaaLoadTest_daa1_special_5m_24

@pshipton
Copy link
Member

pshipton commented May 1, 2023

@AdamBrousseau fyi this failure which appears to be related to win 2019 machines being too slow.

@JasonFengJ9
Copy link
Member Author

JasonFengJ9 commented May 2, 2023 •
edited by pshipton
Loading

JDK11 aarch64_mac 0.38(macaarch64rt2)

java version "11.0.19" 2023-04-18
IBM Semeru Runtime Certified Edition 11.0.19.0-rc1 (build 11.0.19+7)
Eclipse OpenJ9 VM 11.0.19.0-rc1 (build v0.38.0-release-d57d05932, JRE 11 Mac OS X aarch64-64-Bit 20230501_273 (JIT enabled, AOT enabled)
OpenJ9   - d57d05932
OMR      - 855813495
JCL      - 1539bdcd45 based on jdk-11.0.19+7)

[2023-05-01T20:57:49.871Z] variation: Mode145
[2023-05-01T20:57:49.871Z] JVM_OPTIONS:  -Xgcpolicy:gencon -Xshareclasses -Xjit -Xnocompressedrefs 

DLT 17:00:21.322 - Completed 46.7%. Number of tests started=4596 (+830)
DLT 17:00:41.308 - Completed 53.3%. Number of tests started=6227 (+1631)
STF 17:18:25.992 - Heartbeat: Process DLT is still running
DLT 17:18:25.991 - Completed 100.0%. Number of tests started=6345 (+118)
DLT 17:18:25.991 - **POSSIBLE HANG DETECTED**
DLT 17:18:26.072 - Thread completed. Suite=0 thread=2
DLT 17:18:26.072 - Thread completed. Suite=0 thread=0
DLT 17:18:26.099 - Completed 100.0%. Number of tests started=6345 (+0)
DLT 17:18:26.191 - Thread completed. Suite=0 thread=4
DLT 17:18:26.200 - Completed 100.0%. Number of tests started=6345 (+0)
DLT 17:18:26.265 - Thread completed. Suite=0 thread=1
DLT 17:18:26.310 - Completed 100.0%. Number of tests started=6345 (+0)
DLT 17:18:26.330 - Thread completed. Suite=0 thread=3
DLT 17:18:26.360 - Thread completed. Suite=0 thread=5
DLT 17:18:26.421 - Test stopped due to reaching runtime limit
DLT 17:18:26.421 - Load test completed
DLT 17:18:26.421 -   Ran     : 6345
DLT 17:18:26.421 -   Passed  : 6345
DLT 17:18:26.421 -   Failed  : 0
DLT 17:18:26.421 -   Result  : PASSED
STF 17:18:26.496 - **FAILED** Process DLT has hung
STF 17:18:26.496 - Collecting dumps for: DLT
STF 17:18:26.496 - Sending SIG 3 to the java process to generate a javacore

[2023-05-01T21:19:38.403Z] STF 17:18:56.610 - Overall result: **FAILED**
[2023-05-01T21:19:38.403Z] -----------------------------------
[2023-05-01T21:19:38.403Z] DaaLoadTest_daa1_special_5m_8_FAILED

No diagnostics.

@JasonFengJ9
Copy link
Member Author

JDK20 x86-64_windows(win16x64rt2-3)

openjdk version "20.0.1" 2023-04-18
IBM Semeru Runtime Open Edition 20.0.1.0-rc1 (build 20.0.1+9)
Eclipse OpenJ9 VM 20.0.1.0-rc1 (build v0.39.0-release-088b83604, JRE 20 Windows Server 2016 amd64-64-Bit Compressed References 20230418_48 (JIT enabled, AOT enabled)
OpenJ9   - 088b83604
OMR      - e4f52d2e4
JCL      - a8a96d7eb2c based on jdk-20.0.1+9)

[2023-06-10T01:26:02.439Z] variation: Mode107-OSRG
[2023-06-10T01:26:02.824Z] JVM_OPTIONS:  -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation 

2023-06-10T01:48:44.782Z] STF 18:48:44.491 - Redirecting stdout to C:/Users/jenkins/workspace/Test_openjdk20_j9_special.system_x86-64_windows_testList_3/aqa-tests/TKG/output_16863527386082/DaaLoadTest_all_special_5m_24/20230609-182606-DaaLoadTest/results/1.DLT.jvmdump.stdout
[2023-06-10T01:48:44.782Z] STF 18:48:44.515 - Pausing for 30 seconds
[2023-06-10T01:49:19.218Z] DLT 18:47:44.001 - **POSSIBLE HANG DETECTED**
[2023-06-10T01:49:19.218Z] DLT 18:47:59.989 - Completed 100.0%. Number of tests started=159 (+0)
[2023-06-10T01:49:19.218Z] DLT 18:47:59.991 - **POSSIBLE HANG DETECTED**
[2023-06-10T01:49:19.218Z] DLT 18:48:05.063 - **POSSIBLE HANG DETECTED**

[2023-06-10T01:49:19.219Z] STF 18:49:14.522 - Monitoring Report Summary:
[2023-06-10T01:49:19.219Z] STF 18:49:14.522 -   o Process DLT has hung

[2023-06-10T01:49:19.219Z] STF 18:49:15.135 - Overall result: **FAILED**
[2023-06-10T01:49:19.219Z] -----------------------------------
[2023-06-10T01:49:19.219Z] DaaLoadTest_all_special_5m_24_FAILED

@pshipton
Copy link
Member

pshipton commented Jun 12, 2023 •
edited
Loading

@JasonFengJ9 pls ignore DaaLoadTest mode 24 hangs on Windows.
#13477 (comment)

@hzongaro hzongaro self-assigned this Aug 22, 2023
@JasonFengJ9
Copy link
Member Author

JDK21 aarch64_mac milestone 0(macaarch64rt2)

[2023-09-22T19:43:32.558Z] variation: -Xgcpolicy:gencon -Xgc:concurrentScavenge
[2023-09-22T19:43:32.558Z] JVM_OPTIONS:  -Xgcpolicy:gencon -Xgc:concurrentScavenge 

[2023-09-22T19:59:38.816Z] STF 15:59:13.231 - Heartbeat: Process DLT is still running
[2023-09-22T19:59:38.816Z] DLT 15:59:13.244 - Completed 100.0%. Number of tests started=924
[2023-09-22T19:59:38.816Z] DLT 15:59:13.244 - **POSSIBLE HANG DETECTED**

[2023-09-22T19:59:44.913Z] STF 15:59:44.326 - Overall result: **FAILED**
[2023-09-22T19:59:44.913Z] -----------------------------------
[2023-09-22T19:59:44.913Z] DaaLoadTest_daa1_CS_5m_0_FAILED

@hzongaro
Copy link
Member

Moving this to the backlog for now, but I will try to spend some time sorting out whether there are distinct JIT problems here that can be tracked and prioritized as separate issues.

@JasonFengJ9
Copy link
Member Author

JDK11 aarch64_mac(macaarch64rt4)

[2024-03-26T19:20:56.352Z] variation: Mode104
[2024-03-26T19:20:56.352Z] JVM_OPTIONS:  -Xgcpolicy:optthruput -Xjit:count=0,optlevel=hot,gcOnResolve,rtResolve -Xnocompressedrefs 

[2024-03-26T19:50:31.743Z] STF 15:50:01.429 - Heartbeat: Process DLT is still running
[2024-03-26T19:50:31.743Z] DLT 15:50:01.841 - Completed 6.7%. Number of tests started=140
[2024-03-26T19:50:31.743Z] DLT 15:50:01.842 - **POSSIBLE HANG DETECTED**
[2024-03-26T19:50:31.743Z] STF 15:50:01.940 - **FAILED** Process DLT has hung

[2024-03-26T19:50:32.199Z] DLT 15:50:04.677 - Load test completed
[2024-03-26T19:50:32.199Z] DLT 15:50:04.677 -   Ran     : 140
[2024-03-26T19:50:32.199Z] DLT 15:50:04.677 -   Passed  : 140
[2024-03-26T19:50:32.199Z] DLT 15:50:04.677 -   Failed  : 0
[2024-03-26T19:50:32.199Z] DLT 15:50:04.677 -   Result  : PASSED
[2024-03-26T19:50:32.199Z] DLT stderr JVMDUMP039I Processing dump event "user", detail "" at 2024/03/26 15:50:01 - please wait.
[2024-03-26T19:50:32.199Z] DLT stderr JVMDUMP032I JVM requested System dump using '/Users/jenkins/workspace/Test_openjdk11_j9_special.system_aarch64_mac_testList_3/aqa-tests/TKG/output_17114786051176/DaaLoadTest_daa1_special_5m_2/20240326-152056-DaaLoadTest/results/core.20240326.155001.32750.0001.dmp' in response to an event
[2024-03-26T19:50:32.199Z] STF 15:50:31.937 - Monitoring Report Summary:
[2024-03-26T19:50:32.199Z] STF 15:50:31.937 -   o Process DLT has hung
[2024-03-26T19:50:32.199Z] STF 15:50:31.938 - Killing processes: DLT
[2024-03-26T19:50:32.199Z] STF 15:50:31.938 -   o Process DLT pid 32750 is not running
[2024-03-26T19:50:32.199Z] **FAILED** at step 1 (Run daa load test). Expected return value=0 Actual=1 at /Users/jenkins/workspace/Test_openjdk11_j9_special.system_aarch64_mac_testList_3/aqa-tests/TKG/../TKG/output_17114786051176/DaaLoadTest_daa1_special_5m_2/20240326-152056-DaaLoadTest/execute.pl line 96.
[2024-03-26T19:50:32.199Z] STF 15:50:31.968 - **FAILED** execute script failed. Expected return value=0 Actual=1
[2024-03-26T19:50:32.199Z] STF 15:50:31.968 - 
[2024-03-26T19:50:32.199Z] STF 15:50:31.968 - ====================   T E A R D O W N   ====================
[2024-03-26T19:50:32.199Z] STF 15:50:31.968 - Running teardown: perl /Users/jenkins/workspace/Test_openjdk11_j9_special.system_aarch64_mac_testList_3/aqa-tests/TKG/../TKG/output_17114786051176/DaaLoadTest_daa1_special_5m_2/20240326-152056-DaaLoadTest/tearDown.pl
[2024-03-26T19:50:32.199Z] STF 15:50:32.035 - TEARDOWN stage completed
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 - 
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 - =====================   R E S U L T S   =====================
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 - Stage results:
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 -   setUp:     pass
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 -   execute:  *fail*
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 -   teardown:  pass
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 - 
[2024-03-26T19:50:32.199Z] STF 15:50:32.038 - Overall result: **FAILED**
[2024-03-26T19:50:32.199Z] -----------------------------------
[2024-03-26T19:50:32.199Z] DaaLoadTest_daa1_special_5m_2_FAILED

Another similar one DaaLoadTest_daa1_special_5m_24_FAILED at same machine.

@JasonFengJ9
Copy link
Member Author

JDK22 x86-64_windows(win16x64rt-1-8)

[2024-05-03T19:01:23.620Z] variation: Mode107-OSRG
[2024-05-03T19:01:24.002Z] JVM_OPTIONS:  -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation 

[2024-05-03T19:19:26.739Z] DLT 15:19:24.271 - Completed 100.0%. Number of tests started=108 (+0)
[2024-05-03T19:19:36.312Z] DLT 15:19:35.443 - **POSSIBLE HANG DETECTED**
[2024-05-03T19:19:36.312Z] STF 15:19:35.676 - **FAILED** Process DLT has hung
[2024-05-03T19:19:36.312Z] STF 15:19:35.677 - Collecting dumps for: DLT

[2024-05-03T19:21:18.058Z] DaaLoadTest_daa1_special_5m_24_FAILED

@JasonFengJ9
Copy link
Member Author

openjdk21_j9_special.system_x86-64_windows(win19x86-rtp-rt5-1)

[2024-10-08T17:07:40.206Z] variation: Mode107-OSRG
[2024-10-08T17:07:40.206Z] JVM_OPTIONS:  -Xgcpolicy:optthruput -Xdebug -Xrunjdwp:transport=dt_socket,address=8888,server=y,onthrow=no.pkg.foo,launch=echo -Xjit:enableOSR,enableOSROnGuardFailure,count=1,disableAsyncCompilation 

[2024-10-08T17:26:55.266Z] DLT 10:26:51.806 - Completed 100.0%. Number of tests started=47 (+0)
[2024-10-08T17:27:11.998Z] DLT 10:27:04.587 - **POSSIBLE HANG DETECTED**
[2024-10-08T17:27:11.998Z] STF 10:27:04.853 - **FAILED** Process DLT has hung
[2024-10-08T17:27:11.998Z] STF 10:27:04.853 - Collecting dumps for: DLT

[2024-10-08T17:28:42.649Z] DaaLoadTest_daa1_special_5m_24_FAILED

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@hzongaro hzongaro

Labels
bug comp:infra comp:jit prio:high test failure
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
7 participants
@DanHeidinga @0xdaryl @keithc-ca @JasonFengJ9 @pshipton @llxia @hzongaro