CRIU testThreadSleep - expected sleep time #18557

pshipton · 2023-12-04T16:45:28Z

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]

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

pshipton · 2023-12-04T16:45:38Z

@TobiAjila @JasonFengJ9

JasonFengJ9 · 2023-12-08T16:35:00Z

openj9/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java

Line 81 in 21f742f

while (testResult.lockStatus.get() == 0) {

Got the status set by

openj9/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java

Line 63 in 21f742f

testThreadSleepHelper("testThreadSleep NO C/R");

And

openj9/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java

Line 64 in 21f742f

testThread = testThreadSleep();

didn't start before

openj9/test/functional/cmdLineTests/criu/src/org/openj9/criu/JDK11UpTimeoutAdjustmentTest.java

Line 84 in 21f742f

CRIUTestUtils.checkPointJVMNoSetup(criu, CRIUTestUtils.imagePath, false);

Will fix the test.

pshipton · 2024-02-14T12:56:32Z

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]

tajila · 2024-02-14T14:07:37Z

@JasonFengJ9 Please take a look

JasonFengJ9 · 2024-02-14T14:21:12Z

This slipped off my radar, will pick it up.

pshipton · 2024-03-06T17:21:18Z

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

JasonFengJ9 · 2024-03-06T19:12:22Z

The test was running Build #2 (Mar 3, 2024, 1:37:21 PM) before merging of

CRIU time compensation tests reset TestResult.lockStatus #19051
around March 4th, 11am.

Please report the failure afterwards.

pshipton · 2024-03-06T19:22:57Z

The build was for 0.44, did you double deliver the fix to 0.44?

JasonFengJ9 · 2024-03-06T19:34:47Z

The build was for 0.44, did you double deliver the fix to 0.44?

It was a test change, just opened

(v0.44.0-release) CRIU time compensation tests reset TestResult.lockStatus #19086

pshipton · 2024-03-12T14:37:43Z

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 < initializeCriuHooks - checkpointState.hookRecords (000003FF882CDC60), classIterationRestoreHookRecords (000003FF882CEDA0), delayedLockingOperationsRecords (000003FF882CFEE0) [OUT] 09:14:11.816 0x1f16800 j9vm.730 - Before checkpoint, checkpointNanoTimeMonotonic = 1710234851812299381, checkpointNanoUTCTime = 1710234851817054919 [OUT] 09:14:12.516 0x1f16800 j9vm.689 > runInternalJVMCheckpointHooks [OUT] 09:14:12.518 0x1f16800 j9vm.690 < runInternalJVMCheckpointHooks [OUT] 09:14:12.518 0x1f16800 j9vm.732 - Current syslogOptions: error,vital [OUT] 09:14:12.518 0x1f16800 j9vm.729 - Before checkpoint criu_dump(), j9time_nano_time() returns 1710234852514701756, j9time_current_time_nanos() returns 1710234852519456773 [OUT] 09:14:16.899 0x1f16800 j9vm.691 > 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 < runInternalJVMRestoreHooks [OUT] 09:14:16.902 0x1f16800 j9vm.733 - After checkpoint criu_dump(), j9time_nano_time() returns 1710234856898702104, j9time_current_time_nanos() returns 1710234856903457025 [OUT] 09:14:16.902 0x1f16800 j9vm.734 - After restore, restoreNanoUTCTime = 1710234856903457025, checkpointNanoUTCTime = 1710234851817054919, checkpointRestoreTimeDelta = 5086402106, restoreNanoTimeMonotonic = 1710234856898702104, checkpointNanoTimeMonotonic = 1710234851812299381, nanoTimeMonotonicClockDelta = 5086402723 [OUT] 09:14:16.914 0x1f16800 j9vm.743 < Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl [OUT] main: Tue Mar 12 09:14:16 UTC 2024, testThreadSleep NO C/R before sleep(), System.currentTimeMillis(): 1710234856914, System.nanoTime(): 1710234851824045363 [OUT] Thread-0: Tue Mar 12 09:14:16 UTC 2024, testThreadSleep after sleep(), System.currentTimeMillis(): 1710234856925, System.nanoTime(): 1710234851834761527 [OUT] Thread-0: Tue Mar 12 09:14:16 UTC 2024, FAILED: expected sleep time 5000 ms, but the actual elapsed time was: 357581891ns (~357ms) with startNanoTime = 1710234851475891641ns, and endNanoTime = 1710234851833473532ns, CheckpointRestoreNanoTimeDelta: 5086402106ns (~5086ms) [OUT] main: Tue Mar 12 09:14:21 UTC 2024, testThreadSleep NO C/R after sleep(), System.currentTimeMillis(): 1710234861919, System.nanoTime(): 1710234856829238593 [OUT] main: Tue Mar 12 09:14:21 UTC 2024, PASSED: expected sleep time 5000 ms, but the actual elapsed time was: 5003729064ns (~5003ms) with startNanoTime = 1710234851824170826ns, and endNanoTime = 1710234856827899890ns, CheckpointRestoreNanoTimeDelta: 5086402106ns (~5086ms) [OUT] main: Tue Mar 12 09:14:21 UTC 2024, After run test : testThreadSleep, System.currentTimeMillis(): 1710234861922, System.nanoTime(): 1710234856831883973 [OUT] main: Tue Mar 12 09:14:21 UTC 2024, End testThreadSleep, System.currentTimeMillis(): 1710234861922, System.nanoTime(): 1710234856832115440 [OUT] initiate restore [OUT] Removed test output files [OUT] finished script [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: 2969494 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] ```

JasonFengJ9 · 2024-03-12T21:27:22Z

50x grinder - https://openj9-jenkins.osuosl.org/job/Grinder/3371/ - passed
300x grinder - https://openj9-jenkins.osuosl.org/job/Grinder/3372/ - 1/300 failed

pshipton added test failure criu Used to track CRIU snapshot related work labels Dec 4, 2023

JasonFengJ9 self-assigned this Dec 4, 2023

JasonFengJ9 mentioned this issue Mar 1, 2024

CRIU time compensation tests reset TestResult.lockStatus #19051

Merged

r30shah mentioned this issue Mar 7, 2024

Check if block frequency info exist before generating test #19053

Merged

dsouzai mentioned this issue May 24, 2024

Re-enable IProfiler for JITServer #19545

Merged

r30shah mentioned this issue Sep 20, 2024

Warnings Cleanup #20039

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CRIU testThreadSleep - expected sleep time #18557

CRIU testThreadSleep - expected sleep time #18557

pshipton commented Dec 4, 2023

pshipton commented Dec 4, 2023

JasonFengJ9 commented Dec 8, 2023

pshipton commented Feb 14, 2024

tajila commented Feb 14, 2024

JasonFengJ9 commented Feb 14, 2024

pshipton commented Mar 6, 2024

JasonFengJ9 commented Mar 6, 2024

pshipton commented Mar 6, 2024

JasonFengJ9 commented Mar 6, 2024

pshipton commented Mar 12, 2024

JasonFengJ9 commented Mar 12, 2024 •

edited

Loading

CRIU testThreadSleep - expected sleep time #18557

CRIU testThreadSleep - expected sleep time #18557

Comments

pshipton commented Dec 4, 2023

pshipton commented Dec 4, 2023

JasonFengJ9 commented Dec 8, 2023

pshipton commented Feb 14, 2024

tajila commented Feb 14, 2024

JasonFengJ9 commented Feb 14, 2024

pshipton commented Mar 6, 2024

JasonFengJ9 commented Mar 6, 2024

pshipton commented Mar 6, 2024

JasonFengJ9 commented Mar 6, 2024

pshipton commented Mar 12, 2024

JasonFengJ9 commented Mar 12, 2024 • edited Loading

JasonFengJ9 commented Mar 12, 2024 •

edited

Loading