cmdLineTester_criu_nonPortableRestoreJDK11Up testObjectWaitNotify was not found: [Output match: PASSED: expected wait time]

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.

Other

3.29k stars 722 forks source link

Testing: Create CRIU checkpoint image and restore once - testObjectWaitNotify Test start time: 2023/08/03 03:07:44 Eastern Standard Time Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_x86-64_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_x86-64_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_x86-64_linux_Nightly_testList_1/openjdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode -Xtrace:print={j9criu} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED" "org.openj9.criu.JDK11UpTimeoutAdjustmentTest testObjectWaitNotify" 1 1 false false Time spent starting: 4 milliseconds Time spent executing: 18776 milliseconds Test result: FAILED Output from test: [OUT] start running script [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load [OUT] export LD_BIND_NOT=on [OUT] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_x86-64_linux_Nightly_testList_1/openjdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport -Xjit:count=0 -XX:+CRIURestoreNonPortableMode -Xtrace:print={j9criu} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_x86-64_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.JDK11UpTimeoutAdjustmentTest testObjectWaitNotify 1 1 [OUT] Start test name: testObjectWaitNotify [OUT] Before starting testObjectWaitNotify, current thread name: main, Thu Aug 03 03:07:47 EDT 2023, System.currentTimeMillis(): 1691046467240, System.nanoTime(): 7836554543528312 [OUT] testObjectWaitNotify() before wait(), current thread name: Thread-0, Thu Aug 03 03:07:47 EDT 2023, System.currentTimeMillis(): 1691046467869, System.nanoTime(): 7836555172331293 [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Thu Aug 03 03:07:47 EDT 2023, System.currentTimeMillis(): 1691046467872, System.nanoTime(): 7836555175695042 [OUT] 07:07:47.897*0x17000 j9criu.9 > Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl [OUT] 07:07:47.898 0x17000 j9criu.18 - Taking a checkpoint with active clinit [OUT] 07:07:47.910 0x17000 j9criu.13 - Before checkpoint, checkpointNanoTimeMonotonic = 7836555213241443, checkpointNanoUTCTime = 1691046467910510092 [OUT] 07:07:47.933 0x17000 j9criu.12 - Current syslogOptions: error,vital [OUT] 07:07:47.933 0x17000 j9criu.7 - Before checkpoint criu_dump(), j9time_nano_time() returns 7836555236102251, j9time_current_time_nanos() returns 1691046467933370303 [OUT] 07:07:50.190 0x17000 j9criu.15 - After checkpoint criu_dump(), j9time_nano_time() returns 7836557493271761, j9time_current_time_nanos() returns 1691046470190541100 [OUT] 07:07:50.190 0x17000 j9criu.14 - After restore, restoreNanoUTCTime = 1691046470190541100, checkpointNanoUTCTime = 1691046467910510092, checkpointRestoreTimeDelta = 2280031008, restoreNanoTimeMonotonic = 7836557493271761, checkpointNanoTimeMonotonic = 7836555213241443, nanoTimeMonotonicClockDelta = 2280030318 [OUT] 07:07:50.312 0x17000 j9criu.10 < Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl [OUT] Before objWait.notify(), current thread name: main, Thu Aug 03 03:07:55 EDT 2023, System.currentTimeMillis(): 1691046475316, System.nanoTime(): 7836560339428037 [OUT] testObjectWaitNotify() after wait(), current thread name: Thread-0, Thu Aug 03 03:07:55 EDT 2023, System.currentTimeMillis(): 1691046475492, System.nanoTime(): 7836560514896484 [OUT] End testObjectWaitNotify, current thread name: main, Thu Aug 03 03:08:02 EDT 2023, System.currentTimeMillis(): 1691046482882, System.nanoTime(): 7836567904736219 [OUT] Removed test output files [OUT] finished script [ERR] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_x86-64_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 3734323 Killed $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1 >> Success condition was not found: [Output match: PASSED: expected wait time] >> Required condition was found: [Output match: Killed] >> Required condition was found: [Output match: Start test name: testObjectWaitNotify] >> Failure condition was not found: [Output match: CRIU is not enabled] >> Failure condition was not found: [Output match: Operation not permitted] >> Failure condition was not found: [Output match: FAILED: expected wait time] >> Failure condition was not found: [Output match: InterruptedException] >> Success condition was not found: [Output match: Unable to create a thread:] >> Success condition was not found: [Output match: Thread pid mismatch] >> Success condition was not found: [Output match: do not match expected] >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]

[OUT] Before objWait.notify(), current thread name: main, Thu Aug 03 03:07:55 EDT 2023, System.currentTimeMillis(): 1691046475316, System.nanoTime(): 7836560339428037 [OUT] testObjectWaitNotify() after wait(), current thread name: Thread-0, Thu Aug 03 03:07:55 EDT 2023, System.currentTimeMillis(): 1691046475492, System.nanoTime(): 7836560514896484 [OUT] End testObjectWaitNotify, current thread name: main, Thu Aug 03 03:08:02 EDT 2023, System.currentTimeMillis(): 1691046482882, System.nanoTime(): 7836567904736219

JDK17 ppc64le_linux 0.41 milestone 1(ubu20le-svl-rt10-1)

openjdk version "17.0.9" 2023-10-17
IBM Semeru Runtime Open Edition 17.0.9.0-m1 (build 17.0.9+5)
Eclipse OpenJ9 VM 17.0.9.0-m1 (build v0.41.0-release-87d042a68, JRE 17 Linux ppc64le-64-Bit Compressed References 20231017_524 (JIT enabled, AOT enabled)
OpenJ9   - 87d042a68
OMR      - fa7b6ddc7
JCL      - 7e7cdc3f699 based on jdk-17.0.9+5)

[2023-09-06T21:42:27.910Z] Testing: Create CRIU checkpoint image and restore once - testObjectWaitNotify
[2023-09-06T21:42:27.910Z] Test start time: 2023/09/06 14:42:24 Pacific Standard Time
[2023-09-06T21:42:27.910Z] Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_rerun/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_rerun/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_rerun/openjdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9criu} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED" "org.openj9.criu.JDK11UpTimeoutAdjustmentTest testObjectWaitNotify" 1 1 false false
[2023-09-06T21:42:27.910Z] Time spent starting: 16 milliseconds
[2023-09-06T21:42:48.684Z] Time spent executing: 21757 milliseconds
[2023-09-06T21:42:48.684Z] Test result: FAILED
[2023-09-06T21:42:48.684Z] Output from test:
[2023-09-06T21:42:48.684Z]  [OUT] start running script
[2023-09-06T21:42:48.685Z]  [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
[2023-09-06T21:42:48.685Z]  [OUT] export LD_BIND_NOT=on
[2023-09-06T21:42:48.685Z]  [OUT] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_rerun/openjdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport  -Xjit:count=0 -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9criu} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_rerun/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.JDK11UpTimeoutAdjustmentTest testObjectWaitNotify 1 1
[2023-09-06T21:42:48.685Z]  [OUT] Start test name: testObjectWaitNotify
[2023-09-06T21:42:48.685Z]  [OUT] Before starting testObjectWaitNotify, current thread name: main, Wed Sep 06 14:42:29 PDT 2023, System.currentTimeMillis(): 1694036549185, System.nanoTime(): 127776198859081
[2023-09-06T21:42:48.685Z]  [OUT] testObjectWaitNotify() before wait(), current thread name: Thread-0, Wed Sep 06 14:42:30 PDT 2023, System.currentTimeMillis(): 1694036550081, System.nanoTime(): 127777094831315
[2023-09-06T21:42:48.685Z]  [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Wed Sep 06 14:42:30 PDT 2023, System.currentTimeMillis(): 1694036550086, System.nanoTime(): 127777099910762
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:30.128*0x95800          j9criu.9        > Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:30.128 0x95800          j9criu.18       - Taking a checkpoint with active clinit
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:30.139 0x95800          j9criu.13       - Before checkpoint, checkpointNanoTimeMonotonic = 127777152791037, checkpointNanoUTCTime = 1694036550139275610
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:30.181 0x95800          j9criu.12       - Current syslogOptions: error,vital
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:30.182 0x95800          j9criu.7        - Before checkpoint criu_dump(), j9time_nano_time() returns 127777195770842, j9time_current_time_nanos() returns 1694036550182255486
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:32.350 0x95800          j9criu.15       - After checkpoint criu_dump(), j9time_nano_time() returns 127779363800640, j9time_current_time_nanos() returns 1694036552350285703
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:32.350 0x95800          j9criu.14       - After restore, restoreNanoUTCTime = 1694036552350285703, checkpointNanoUTCTime = 1694036550139275610, checkpointRestoreTimeDelta = 2211010093, restoreNanoTimeMonotonic = 127779363800640, checkpointNanoTimeMonotonic = 127777152791037, nanoTimeMonotonicClockDelta = 2211009603
[2023-09-06T21:42:48.685Z]  [OUT] 21:42:32.373 0x95800          j9criu.10       < Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl
[2023-09-06T21:42:48.685Z]  [OUT] Before objWait.notify(), current thread name: main, Wed Sep 06 14:42:37 PDT 2023, System.currentTimeMillis(): 1694036557383, System.nanoTime(): 127782186262401
[2023-09-06T21:42:48.685Z]  [OUT] testObjectWaitNotify() after wait(), current thread name: Thread-0, Wed Sep 06 14:42:37 PDT 2023, System.currentTimeMillis(): 1694036557752, System.nanoTime(): 127782555352339
[2023-09-06T21:42:48.685Z]  [OUT] End testObjectWaitNotify, current thread name: main, Wed Sep 06 14:42:45 PDT 2023, System.currentTimeMillis(): 1694036565578, System.nanoTime(): 127790380529210
[2023-09-06T21:42:48.685Z]  [OUT] Removed test output files
[2023-09-06T21:42:48.685Z]  [OUT] finished script
[2023-09-06T21:42:48.685Z]  [ERR] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_rerun/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 382527 Killed                  $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
[2023-09-06T21:42:48.685Z] >> Success condition was not found: [Output match: PASSED: expected wait time]
[2023-09-06T21:42:48.685Z] >> Required condition was found: [Output match: Killed]
[2023-09-06T21:42:48.685Z] >> Required condition was found: [Output match: Start test name: testObjectWaitNotify]
[2023-09-06T21:42:48.685Z] >> Failure condition was not found: [Output match: CRIU is not enabled]
[2023-09-06T21:42:48.685Z] >> Failure condition was not found: [Output match: Operation not permitted]
[2023-09-06T21:42:48.685Z] >> Failure condition was not found: [Output match: FAILED: expected wait time]
[2023-09-06T21:42:48.685Z] >> Failure condition was not found: [Output match: InterruptedException]
[2023-09-06T21:42:48.685Z] >> Success condition was not found: [Output match: Unable to create a thread:]
[2023-09-06T21:42:48.685Z] >> Success condition was not found: [Output match: Thread pid mismatch]
[2023-09-06T21:42:48.685Z] >> Success condition was not found: [Output match: do not match expected]
[2023-09-06T21:42:48.685Z] >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
[2023-09-06T21:42:48.685Z] >> Failure condition was not found: [Output match: User requested Java dump using]

[2023-09-06T21:44:00.369Z] ---TEST RESULTS---
[2023-09-06T21:44:00.369Z] Number of PASSED tests: 4 out of 5
[2023-09-06T21:44:00.369Z] Number of FAILED tests: 1 out of 5
[2023-09-06T21:44:00.369Z] 
[2023-09-06T21:44:00.369Z] ---SUMMARY OF FAILED TESTS---
[2023-09-06T21:44:00.369Z] Create CRIU checkpoint image and restore once - testObjectWaitNotify
[2023-09-06T21:44:00.369Z] -----------------------------
[2023-09-06T21:44:00.369Z] 
[2023-09-06T21:44:00.369Z] -----------------------------------
[2023-09-06T21:44:00.369Z] cmdLineTester_criu_nonPortableRestoreJDK11Up_2_FAILED

Again, there was no either PASSED or FAILED message, and the test failed since no Success condition was found.

50x internal grinder - reproduce once at ubu20le-svl-rt12-1

Testing: Create CRIU checkpoint image and restore once - testObjectWaitNotify Test start time: 2023/09/15 06:06:06 Coordinated Universal Time Running command: bash /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/openjdkbinary/j2sdk-image/bin/java " -Xjit:count=0 -XX:+CRIURestoreNonPortableMode -Xtrace:print={j9criu} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED" "org.openj9.criu.JDK11UpTimeoutAdjustmentTest testObjectWaitNotify" 1 1 false false Time spent starting: 7 milliseconds Time spent executing: 20234 milliseconds Test result: FAILED Output from test: [OUT] start running script [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load [OUT] export LD_BIND_NOT=on [OUT] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/openjdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport -Xjit:count=0 -XX:+CRIURestoreNonPortableMode -Xtrace:print={j9criu} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.JDK11UpTimeoutAdjustmentTest testObjectWaitNotify 1 1 [OUT] Start test name: testObjectWaitNotify [OUT] Before starting testObjectWaitNotify, current thread name: main, Fri Sep 15 06:06:10 UTC 2023, System.currentTimeMillis(): 1694757970828, System.nanoTime(): 12660350074215948 [OUT] testObjectWaitNotify() before wait(), current thread name: Thread-0, Fri Sep 15 06:06:11 UTC 2023, System.currentTimeMillis(): 1694757971639, System.nanoTime(): 12660350884971560 [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Fri Sep 15 06:06:11 UTC 2023, System.currentTimeMillis(): 1694757971643, System.nanoTime(): 12660350888636664 [OUT] 06:06:11.674*0x95800 j9criu.9 > Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl [OUT] 06:06:11.675 0x95800 j9criu.18 - Taking a checkpoint with active clinit [OUT] 06:06:11.683 0x95800 j9criu.13 - Before checkpoint, checkpointNanoTimeMonotonic = 12660350928935801, checkpointNanoUTCTime = 1694757971683667167 [OUT] 06:06:11.707 0x95800 j9criu.12 - Current syslogOptions: error,vital [OUT] 06:06:11.707 0x95800 j9criu.7 - Before checkpoint criu_dump(), j9time_nano_time() returns 12660350952967670, j9time_current_time_nanos() returns 1694757971707699045 [OUT] 06:06:13.877 0x95800 j9criu.15 - After checkpoint criu_dump(), j9time_nano_time() returns 12660353122942892, j9time_current_time_nanos() returns 1694757973877674584 [OUT] 06:06:13.877 0x95800 j9criu.14 - After restore, restoreNanoUTCTime = 1694757973877674584, checkpointNanoUTCTime = 1694757971683667167, checkpointRestoreTimeDelta = 2194007417, restoreNanoTimeMonotonic = 12660353122942892, checkpointNanoTimeMonotonic = 12660350928935801, nanoTimeMonotonicClockDelta = 2194007091 [OUT] 06:06:13.916 0x95800 j9criu.10 < Java_org_eclipse_openj9_criu_CRIUSupport_checkpointJVMImpl [OUT] Before objWait.notify(), current thread name: main, Fri Sep 15 06:06:18 UTC 2023, System.currentTimeMillis(): 1694757978932, System.nanoTime(): 12660355983268193 [OUT] testObjectWaitNotify() after wait(), current thread name: Thread-0, Fri Sep 15 06:06:19 UTC 2023, System.currentTimeMillis(): 1694757979216, System.nanoTime(): 12660356268216732 [OUT] End testObjectWaitNotify, current thread name: main, Fri Sep 15 06:06:26 UTC 2023, System.currentTimeMillis(): 1694757986692, System.nanoTime(): 12660363743918159 [OUT] Removed test output files [OUT] finished script [ERR] /home/jenkins/workspace/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 2684690 Killed $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1 >> Success condition was not found: [Output match: PASSED: expected wait time] >> Required condition was found: [Output match: Killed] >> Required condition was found: [Output match: Start test name: testObjectWaitNotify] >> Failure condition was not found: [Output match: CRIU is not enabled] >> Failure condition was not found: [Output match: Operation not permitted] >> Failure condition was not found: [Output match: FAILED: expected wait time] >> Failure condition was not found: [Output match: InterruptedException] >> Success condition was not found: [Output match: Unable to create a thread:] >> Success condition was not found: [Output match: Thread pid mismatch] >> Success condition was not found: [Output match: do not match expected] >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70] >> Failure condition was not found: [Output match: User requested Java dump using]

eclipse-openj9 / openj9

cmdLineTester_criu_nonPortableRestoreJDK11Up testObjectWaitNotify was not found: [Output match: PASSED: expected wait time] #17909