openj9
openj9 copied to clipboard
Published
20 hours ago •
eclipse-openj9
eclipse-openj9
CRIU testThreadSleep - expected sleep time
https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_s390x_linux_Nightly_testList_0/110/ cmdLineTester_criu_nonPortableRestoreJDK11Up_3
Testing: Create CRIU checkpoint image and restore once - testThreadSleep
Test start time: 2023/12/02 02:47:07 Coordinated Universal Time
Running command: bash /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_s390x_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_s390x_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_s390x_linux_Nightly_testList_0/jdkbinary/j2sdk-image/bin/java " -XX:+JVMPortableRestoreMode -Xtrace:print={j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED" "org.openj9.criu.JDK11UpTimeoutAdjustmentTest testThreadSleep" 1 1 false false
Time spent starting: 14 milliseconds
Time spent executing: 17367 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_openjdk21_j9_sanity.functional_s390x_linux_Nightly_testList_0/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport -XX:+JVMPortableRestoreMode -Xtrace:print={j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_s390x_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.JDK11UpTimeoutAdjustmentTest testThreadSleep 1 1
[OUT] Start test name: testThreadSleep
[OUT] Before starting testThreadSleep, current thread name: main, Sat Dec 02 02:47:08 UTC 2023, System.currentTimeMillis(): 1701485228386, System.nanoTime(): 1701485228384483617
[OUT] testThreadSleep NO C/R before sleep(), current thread name: main, Sat Dec 02 02:47:08 UTC 2023, System.currentTimeMillis(): 1701485228497, System.nanoTime(): 1701485228495254093
[OUT] testThreadSleep NO C/R after sleep(), current thread name: main, Sat Dec 02 02:47:13 UTC 2023, System.currentTimeMillis(): 1701485233502, System.nanoTime(): 1701485233500872284
[OUT] PASSED: expected sleep time 5000 ms, but the actual elapsed time was: 5004933017ns (~5004ms) with startNanoTime = 1701485228495342691ns, and endNanoTime = 1701485233500275708ns, CheckpointRestoreNanoTimeDelta: 0ns (~0ms)
[OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Sat Dec 02 02:47:13 UTC 2023, System.currentTimeMillis(): 1701485233581, System.nanoTime(): 1701485233579238279
[OUT] 02:47:14.047*0x142e800 j9vm.728 > Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
[OUT] 02:47:14.047 0x142e800 j9vm.731 - Checkpoint blocked because thread=00000000016E4C00 is in method=00000000014ED8B0 due to delay code 1
[OUT] testThreadSleep before sleep(), current thread name: Thread-0, Sat Dec 02 02:47:13 UTC 2023, System.currentTimeMillis(): 1701485233582, System.nanoTime(): 1701485233580880876
[OUT] 02:47:14.052 0x142e800 j9vm.727 - Taking a checkpoint with active clinit
[OUT] 02:47:14.052 0x142e800 j9vm.684 > initializeCriuHooks
[OUT] 02:47:14.052 0x142e800 j9vm.720 - initializeCriuHooks() checkpoint CPU count (4)
[OUT] 02:47:14.052 0x142e800 j9vm.723 * - initializeCriuHooks() j.u.Random class not found
[OUT] 02:47:14.052 0x142e800 j9vm.717 < initializeCriuHooks - checkpointState.hookRecords (000003FF802CE990), classIterationRestoreHookRecords (000003FF802CFA70), delayedLockingOperationsRecords (000003FF802D0BB0)
[OUT] 02:47:14.054 0x142e800 j9vm.730 - Before checkpoint, checkpointNanoTimeMonotonic = 1701485234052372334, checkpointNanoUTCTime = 1701485234055172331
[OUT] 02:47:14.860 0x142e800 j9vm.689 > runInternalJVMCheckpointHooks
[OUT] 02:47:14.867 0x142e800 j9vm.690 < runInternalJVMCheckpointHooks
[OUT] 02:47:14.867 0x142e800 j9vm.732 - Current syslogOptions: error,vital
[OUT] 02:47:14.867 0x142e800 j9vm.729 - Before checkpoint criu_dump(), j9time_nano_time() returns 1701485234865408854, j9time_current_time_nanos() returns 1701485234868209023
[OUT] 02:47:20.036 0x142e800 j9vm.691 > runInternalJVMRestoreHooks
[OUT] 02:47:20.036 0x142e800 j9vm.721 - Reset j.l.VirtualThread.ForkJoinPool.parallelism: same cpu count (4) between C/R
[OUT] 02:47:20.036 0x142e800 j9vm.692 < runInternalJVMRestoreHooks
[OUT] 02:47:20.036 0x142e800 j9vm.733 - After checkpoint criu_dump(), j9time_nano_time() returns 1701485240034664580, j9time_current_time_nanos() returns 1701485240037464461
[OUT] 02:47:20.036 0x142e800 j9vm.734 - After restore, restoreNanoUTCTime = 1701485240037464461, checkpointNanoUTCTime = 1701485234055172331, checkpointRestoreTimeDelta = 5982292130, restoreNanoTimeMonotonic = 1701485240034664580, checkpointNanoTimeMonotonic = 1701485234052372334, nanoTimeMonotonicClockDelta = 5982292246
[OUT] 02:47:20.041 0x142e800 j9vm.743 < Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
[OUT] testThreadSleep NO C/R before sleep(), current thread name: main, Sat Dec 02 02:47:20 UTC 2023, System.currentTimeMillis(): 1701485240041, System.nanoTime(): 1701485234057426735
[OUT] testThreadSleep after sleep(), current thread name: Thread-0, Sat Dec 02 02:47:20 UTC 2023, System.currentTimeMillis(): 1701485240046, System.nanoTime(): 1701485234062425695
[OUT] FAILED: expected sleep time 5000 ms, but the actual elapsed time was: 15690615ns (~15ms) with startNanoTime = 1701485234046654547ns, and endNanoTime = 1701485234062345162ns, CheckpointRestoreNanoTimeDelta: 5982292130ns (~5982ms)
[OUT] testThreadSleep NO C/R after sleep(), current thread name: main, Sat Dec 02 02:47:25 UTC 2023, System.currentTimeMillis(): 1701485245046, System.nanoTime(): 1701485239062020431
[OUT] PASSED: expected sleep time 5000 ms, but the actual elapsed time was: 5004279286ns (~5004ms) with startNanoTime = 1701485234057584602ns, and endNanoTime = 1701485239061863888ns, CheckpointRestoreNanoTimeDelta: 5982292130ns (~5982ms)
[OUT] After run test : testThreadSleep, current thread name: main, Sat Dec 02 02:47:25 UTC 2023, System.currentTimeMillis(): 1701485245047, System.nanoTime(): 1701485239062999783
[OUT] End testThreadSleep, current thread name: main, Sat Dec 02 02:47:25 UTC 2023, System.currentTimeMillis(): 1701485245047, System.nanoTime(): 1701485239063237642
[OUT] Removed test output files
[OUT] finished script
[ERR] /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_s390x_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 1115295 Killed $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
>> Success condition was found: [Output match: PASSED: expected sleep time]
>> Required condition was found: [Output match: Killed]
>> Required condition was found: [Output match: Start test name: testThreadSleep]
>> Failure condition was not found: [Output match: CRIU is not enabled]
>> Failure condition was not found: [Output match: Operation not permitted]
>> Failure condition was found: [Output match: FAILED: expected sleep 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]
https://github.com/eclipse-openj9/openj9/blob/21f742fbc5756e350830a53d78dd3f4e8e48fba1/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java#L81 Got the status set by https://github.com/eclipse-openj9/openj9/blob/21f742fbc5756e350830a53d78dd3f4e8e48fba1/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java#L63 And https://github.com/eclipse-openj9/openj9/blob/21f742fbc5756e350830a53d78dd3f4e8e48fba1/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java#L64 didn't start before https://github.com/eclipse-openj9/openj9/blob/21f742fbc5756e350830a53d78dd3f4e8e48fba1/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java#L84 Will fix the test.
https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/7 cmdLineTester_criu_nonPortableRestoreJDK11Up_0
04:42:00 Testing: Create CRIU checkpoint image and restore once - testThreadSleep
04:42:00 Test start time: 2024/02/14 09:41:57 Coordinated Universal Time
04:42:00 Running command: bash /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java " -Xjit -XX:+CRIURestoreNonPortableMode -Xtrace:print={j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED" "org.openj9.criu.JDK11UpTimeoutAdjustmentTest testThreadSleep" 1 1 false false
04:42:00 Time spent starting: 1 milliseconds
04:42:14 Time spent executing: 16173 milliseconds
04:42:14 Test result: FAILED
04:42:14 Output from test:
04:42:14 [OUT] start running script
04:42:14 [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
04:42:14 [OUT] export LD_BIND_NOT=on
04:42:14 [OUT] /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport -Xjit -XX:+CRIURestoreNonPortableMode -Xtrace:print={j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.JDK11UpTimeoutAdjustmentTest testThreadSleep 1 1
04:42:14 [OUT] Start test name: testThreadSleep
04:42:14 [OUT] Before starting testThreadSleep, current thread name: main, Wed Feb 14 09:41:58 UTC 2024, System.currentTimeMillis(): 1707903718608, System.nanoTime(): 1707903718604035143
04:42:14 [OUT] testThreadSleep NO C/R before sleep(), current thread name: main, Wed Feb 14 09:41:58 UTC 2024, System.currentTimeMillis(): 1707903718718, System.nanoTime(): 1707903718714809322
04:42:14 [OUT] testThreadSleep NO C/R after sleep(), current thread name: main, Wed Feb 14 09:42:03 UTC 2024, System.currentTimeMillis(): 1707903723720, System.nanoTime(): 1707903723716448937
04:42:14 [OUT] PASSED: expected sleep time 5000 ms, but the actual elapsed time was: 5000971909ns (~5000ms) with startNanoTime = 1707903718714895677ns, and endNanoTime = 1707903723715867586ns, CheckpointRestoreNanoTimeDelta: 0ns (~0ms)
04:42:14 [OUT] Performing CRIUSupport.checkpointJVM(), current thread name: main, Wed Feb 14 09:42:03 UTC 2024, System.currentTimeMillis(): 1707903723740, System.nanoTime(): 1707903723736183231
04:42:14 [OUT] testThreadSleep before sleep(), current thread name: Thread-0, Wed Feb 14 09:42:03 UTC 2024, System.currentTimeMillis(): 1707903723740, System.nanoTime(): 1707903723736776839
04:42:14 [OUT] 09:42:04.338*0xf2800 j9vm.728 > Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
04:42:14 [OUT] 09:42:04.339 0xf2800 j9vm.727 - Taking a checkpoint with active clinit
04:42:14 [OUT] 09:42:04.339 0xf2800 j9vm.684 > initializeCriuHooks
04:42:14 [OUT] 09:42:04.339 0xf2800 j9vm.720 - initializeCriuHooks() checkpoint CPU count (4)
04:42:14 [OUT] 09:42:04.339 0xf2800 j9vm.723 * - initializeCriuHooks() j.u.Random class not found
04:42:14 [OUT] 09:42:04.339 0xf2800 j9vm.717 < initializeCriuHooks - checkpointState.hookRecords (000003FF7C2D0D20), classIterationRestoreHookRecords (000003FF7C2D1E60), delayedLockingOperationsRecords (000003FF7C2D2FA0)
04:42:14 [OUT] 09:42:04.340 0xf2800 j9vm.730 - Before checkpoint, checkpointNanoTimeMonotonic = 1707903724336167865, checkpointNanoUTCTime = 1707903724340424763
04:42:14 [OUT] 09:42:06.247 0xf2800 j9vm.689 > runInternalJVMCheckpointHooks
04:42:14 [OUT] 09:42:06.250 0xf2800 j9vm.690 < runInternalJVMCheckpointHooks
04:42:14 [OUT] 09:42:06.250 0xf2800 j9vm.732 - Current syslogOptions: error,vital
04:42:14 [OUT] 09:42:06.250 0xf2800 j9vm.729 - Before checkpoint criu_dump(), j9time_nano_time() returns 1707903726246836352, j9time_current_time_nanos() returns 1707903726251093406
04:42:14 [OUT] 09:42:08.905 0xf2800 j9vm.691 > runInternalJVMRestoreHooks
04:42:14 [OUT] 09:42:08.905 0xf2800 j9vm.721 - Reset j.l.VirtualThread.ForkJoinPool.parallelism: same cpu count (4) between C/R
04:42:14 [OUT] 09:42:08.905 0xf2800 j9vm.692 < runInternalJVMRestoreHooks
04:42:14 [OUT] 09:42:08.905 0xf2800 j9vm.733 - After checkpoint criu_dump(), j9time_nano_time() returns 1707903728901641283, j9time_current_time_nanos() returns 1707903728905898083
04:42:14 [OUT] 09:42:08.905 0xf2800 j9vm.734 - After restore, restoreNanoUTCTime = 1707903728905898083, checkpointNanoUTCTime = 1707903724340424763, checkpointRestoreTimeDelta = 4565473320, restoreNanoTimeMonotonic = 1707903728901641283, checkpointNanoTimeMonotonic = 1707903724336167865, nanoTimeMonotonicClockDelta = 4565473418
04:42:14 [OUT] 09:42:08.921 0xf2800 j9vm.743 < Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
04:42:14 [OUT] testThreadSleep NO C/R before sleep(), current thread name: main, Wed Feb 14 09:42:08 UTC 2024, System.currentTimeMillis(): 1707903728921, System.nanoTime(): 1707903724351946837
04:42:14 [OUT] testThreadSleep after sleep(), current thread name: Thread-0, Wed Feb 14 09:42:08 UTC 2024, System.currentTimeMillis(): 1707903728931, System.nanoTime(): 1707903724362244420
04:42:14 [OUT] FAILED: expected sleep time 5000 ms, but the actual elapsed time was: 625333318ns (~625ms) with startNanoTime = 1707903723736871161ns, and endNanoTime = 1707903724362204479ns, CheckpointRestoreNanoTimeDelta: 4565473320ns (~4565ms)
04:42:14 [OUT] testThreadSleep NO C/R after sleep(), current thread name: main, Wed Feb 14 09:42:13 UTC 2024, System.currentTimeMillis(): 1707903733927, System.nanoTime(): 1707903729358379760
04:42:14 [OUT] PASSED: expected sleep time 5000 ms, but the actual elapsed time was: 5000103028ns (~5000ms) with startNanoTime = 1707903724352085396ns, and endNanoTime = 1707903729352188424ns, CheckpointRestoreNanoTimeDelta: 4565473320ns (~4565ms)
04:42:14 [OUT] After run test : testThreadSleep, current thread name: main, Wed Feb 14 09:42:13 UTC 2024, System.currentTimeMillis(): 1707903733928, System.nanoTime(): 1707903729359127716
04:42:14 [OUT] End testThreadSleep, current thread name: main, Wed Feb 14 09:42:13 UTC 2024, System.currentTimeMillis(): 1707903733928, System.nanoTime(): 1707903729359276438
04:42:14 [OUT] Removed test output files
04:42:14 [OUT] finished script
04:42:14 [ERR] /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 1536075 Killed $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
04:42:14 >> Success condition was found: [Output match: PASSED: expected sleep time]
04:42:14 >> Required condition was found: [Output match: Killed]
04:42:14 >> Required condition was found: [Output match: Start test name: testThreadSleep]
04:42:14 >> Failure condition was not found: [Output match: CRIU is not enabled]
04:42:14 >> Failure condition was not found: [Output match: Operation not permitted]
04:42:14 >> Failure condition was found: [Output match: FAILED: expected sleep time]
04:42:14 >> Failure condition was not found: [Output match: InterruptedException]
04:42:14 >> Success condition was not found: [Output match: Unable to create a thread:]
04:42:14 >> Success condition was not found: [Output match: Thread pid mismatch]
04:42:14 >> Success condition was not found: [Output match: do not match expected]
04:42:14 >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
04:42:14 >> Failure condition was not found: [Output match: User requested Java dump using]
https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.functional_s390x_linux_Release_testList_1/2 - ub20-390-6 cmdLineTester_criu_nonPortableRestoreJDK11Up_2 Testing: Create CRIU checkpoint image and restore once - testThreadSleep
The test was running Build #2 (Mar 3, 2024, 1:37:21 PM) before merging of
- https://github.com/eclipse-openj9/openj9/pull/19051 around March 4th, 11am.
Please report the failure afterwards.
The build was for 0.44, did you double deliver the fix to 0.44?
It was a test change, just opened
- https://github.com/eclipse-openj9/openj9/pull/19086
https://openj9-jenkins.osuosl.org/job/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/25 cmdLineTester_criu_nonPortableRestoreJDK11Up_3
Test output
``` Testing: Create CRIU checkpoint image and restore once - testThreadSleep Test start time: 2024/03/12 09:14:05 Coordinated Universal Time Running command: bash /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java " -XX:+JVMPortableRestoreMode -Xtrace:print={j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED" "org.openj9.criu.JDK11UpTimeoutAdjustmentTest testThreadSleep" 1 1 false false Time spent starting: 11 milliseconds Time spent executing: 16670 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_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport -XX:+JVMPortableRestoreMode -Xtrace:print={j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports=java.base/jdk.internal.misc=ALL-UNNAMED --add-exports=java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk22_j9_sanity.functional_s390x_linux_Nightly_testList_1/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.JDK11UpTimeoutAdjustmentTest testThreadSleep 1 1 [OUT] Start test name: testThreadSleep [OUT] main: Tue Mar 12 09:14:06 UTC 2024, Before starting testThreadSleep, System.currentTimeMillis(): 1710234846343, System.nanoTime(): 1710234846339069901 [OUT] main: Tue Mar 12 09:14:06 UTC 2024, testThreadSleep NO C/R before sleep(), System.currentTimeMillis(): 1710234846432, System.nanoTime(): 1710234846428203908 [OUT] main: Tue Mar 12 09:14:11 UTC 2024, testThreadSleep NO C/R after sleep(), System.currentTimeMillis(): 1710234851433, System.nanoTime(): 1710234851429935344 [OUT] main: Tue Mar 12 09:14:11 UTC 2024, PASSED: expected sleep time 5000 ms, but the actual elapsed time was: 5001006258ns (~5001ms) with startNanoTime = 1710234846428309844ns, and endNanoTime = 1710234851429316102ns, CheckpointRestoreNanoTimeDelta: 0ns (~0ms) [OUT] Thread-0: Tue Mar 12 09:14:11 UTC 2024, testThreadSleep before sleep(), System.currentTimeMillis(): 1710234851476, System.nanoTime(): 1710234851472938127 [OUT] main: Tue Mar 12 09:14:11 UTC 2024, Performing CRIUSupport.checkpointJVM(), System.currentTimeMillis(): 1710234851480, System.nanoTime(): 1710234851476212001 [OUT] 09:14:11.815*0x1f16800 j9vm.728 > Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl [OUT] 09:14:11.815 0x1f16800 j9vm.727 - Taking a checkpoint with active clinit [OUT] 09:14:11.815 0x1f16800 j9vm.684 > initializeCriuHooks [OUT] 09:14:11.815 0x1f16800 j9vm.720 - initializeCriuHooks() checkpoint CPU count (4) [OUT] 09:14:11.815 0x1f16800 j9vm.723 * - initializeCriuHooks() j.u.Random class not found [OUT] 09:14:11.815 0x1f16800 j9vm.717 runInternalJVMCheckpointHooks [OUT] 09:14:12.518 0x1f16800 j9vm.690 runInternalJVMRestoreHooks [OUT] 09:14:16.899 0x1f16800 j9vm.721 - Reset j.l.VirtualThread.ForkJoinPool.parallelism: same cpu count (4) between C/R [OUT] 09:14:16.902 0x1f16800 j9vm.692 testOutput 2>&1 >> Success condition was found: [Output match: PASSED: expected sleep time] >> Required condition was found: [Output match: Killed] >> Required condition was found: [Output match: Start test name: testThreadSleep] >> Failure condition was not found: [Output match: CRIU is not enabled] >> Failure condition was not found: [Output match: Operation not permitted] >> Failure condition was found: [Output match: FAILED: expected sleep 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] ```
50x grinder - https://openj9-jenkins.osuosl.org/job/Grinder/3371/ - passed 300x grinder - https://openj9-jenkins.osuosl.org/job/Grinder/3372/ - 1/300 failed