search

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.28k stars 721 forks source link

CRIU testTimeCompensation failure #20464

Open pshipton opened 6 days ago

pshipton commented 6 days ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_aarch64_linux_OMR_testList_0/176 cmdLineTester_criu_nonPortableRestore_10

09:07:37  Testing: Create CRIU checkpoint image and restore once - testTimeCompensation
09:07:37  Test start time: 2024/10/31 13:07:30 Coordinated Universal Time
09:07:37  Running command: bash /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_OMR_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_OMR_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_OMR_testList_0/jdkbinary/j2sdk-image/bin/java " -XX:+DebugOnRestore -Xjit:count=0  -Xtrace:print={j9jcl.533,j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED" org.openj9.criu.TimeChangeTest testTimeCompensation 1 false false
09:07:37  Time spent starting: 8 milliseconds
09:08:44  Time spent executing: 64124 milliseconds
09:08:44  Test result: FAILED
09:08:44  Output from test:
09:08:44   [OUT] start running script
09:08:44   [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
09:08:44   [OUT] export LD_BIND_NOT=on
09:08:44   [OUT] /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_OMR_testList_0/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport  -XX:+DebugOnRestore -Xjit:count=0  -Xtrace:print={j9jcl.533,j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_OMR_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.TimeChangeTest testTimeCompensation 1
09:08:44   [OUT] main: Thu Oct 31 13:07:58 UTC 2024, testTimeCompensation() starts, System.currentTimeMillis(): 1730380092804, System.nanoTime(): 3563566504656046
09:08:44   [OUT] testTimeCompensation() sleep 100ms checkElapseTime starts, current thread name: main, Thu Oct 31 13:08:15 UTC 2024, System.currentTimeMillis() 1730380095315, System.nanoTime() 3563569015711166
09:08:44   [OUT] testTimeCompensation() sleep 100ms: startMillisTime (1730380095202ms) startNanoTime (3563568902005236ns) currentMillisTime (1730380095307ms) currentNanoTime (3563569007166425ns) elapsedMillisTime (105ms) elapsedNanoTime (105161189ns)
09:08:44   [OUT] testTimeCompensation() sleep 100ms checkElapseTime ends, current thread name: main, Thu Oct 31 13:08:15 UTC 2024, System.currentTimeMillis() 1730380095512, System.nanoTime() 3563569212139471
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Thu Oct 31 13:08:15 UTC 2024, System.currentTimeMillis() 1730380095656, System.nanoTime() 3563569355882894
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms: startMillisTime (1730380095512ms) startNanoTime (3563569212222094ns) currentMillisTime (1730380095655ms) currentNanoTime (3563569355798545ns) elapsedMillisTime (143ms) elapsedNanoTime (143576451ns)
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Thu Oct 31 13:08:15 UTC 2024, System.currentTimeMillis() 1730380095656, System.nanoTime() 3563569356220115
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Thu Oct 31 13:08:17 UTC 2024, System.currentTimeMillis() 1730380097608, System.nanoTime() 3563571308811156
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 2s: startMillisTime (1730380095608ms) startNanoTime (3563569308065227ns) currentMillisTime (1730380097608ms) currentNanoTime (3563571308715907ns) elapsedMillisTime (2000ms) elapsedNanoTime (2000650680ns)
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Thu Oct 31 13:08:17 UTC 2024, System.currentTimeMillis() 1730380097609, System.nanoTime() 3563571309162226
09:08:44   [OUT] testTimeCompensation() preCheckpoint checkElapseTime starts, current thread name: main, Thu Oct 31 13:08:17 UTC 2024, System.currentTimeMillis() 1730380097646, System.nanoTime() 3563571345903110
09:08:44   [OUT] testTimeCompensation() preCheckpoint: startMillisTime (1730380095608ms) startNanoTime (3563569308714418ns) currentMillisTime (1730380097646ms) currentNanoTime (3563571345870185ns) elapsedMillisTime (2038ms) elapsedNanoTime (2037155767ns)
09:08:44   [OUT] testTimeCompensation() preCheckpoint checkElapseTime ends, current thread name: main, Thu Oct 31 13:08:17 UTC 2024, System.currentTimeMillis() 1730380097646, System.nanoTime() 3563571346071533
09:08:44   [OUT] main: Thu Oct 31 13:08:17 UTC 2024, Performing CRIUSupport.checkpointJVM(), System.currentTimeMillis(): 1730380097657, System.nanoTime(): 3563571356889945
09:08:44   [OUT] 13:08:17.754*0xd800            j9vm.728      > Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
09:08:44   [OUT] 13:08:17.755 0xd800            j9vm.727      - Taking a checkpoint with active clinit
09:08:44   [OUT] 13:08:17.755 0xd800            j9vm.684      > initializeCriuHooks
09:08:44   [OUT] 13:08:17.755 0xd800            j9vm.720      - initializeCriuHooks() checkpoint CPU count (4)
09:08:44   [OUT] 13:08:17.755 0xd800            j9vm.723    * - initializeCriuHooks() j.u.Random class not found
09:08:44   [OUT] 13:08:17.755 0xd800            j9vm.717      < initializeCriuHooks - checkpointState.hookRecords (0000FFFF9039ABE0), classIterationRestoreHookRecords (0000FFFF9039BD20), delayedLockingOperationsRecords (0000FFFF9039CE60)
09:08:44   [OUT] testTimeCompensation() preCheckpointHook checkElapseTime starts, current thread name: main, Thu Oct 31 13:08:17 UTC 2024, System.currentTimeMillis() 1730380097785, System.nanoTime() 3563571484889744
09:08:44   [OUT] testTimeCompensation() preCheckpointHook: startMillisTime (1730380095608ms) startNanoTime (3563569308714418ns) currentMillisTime (1730380097784ms) currentNanoTime (3563571484843094ns) elapsedMillisTime (2176ms) elapsedNanoTime (2176128676ns)
09:08:44   [OUT] testTimeCompensation() preCheckpointHook checkElapseTime ends, current thread name: main, Thu Oct 31 13:08:17 UTC 2024, System.currentTimeMillis() 1730380097785, System.nanoTime() 3563571485049842
09:08:44   [OUT] 13:08:17.785 0xd800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFF22510
09:08:44   [OUT] 13:08:17.785 0xd800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFF22B28
09:08:44   [OUT] 13:08:17.831 0xd800            j9vm.730      - Before checkpoint, checkpointNanoTimeMonotonic = 3563571531081207, checkpointNanoUTCTime = 1730380097831225383
09:08:44   [OUT] 13:08:25.664 0xd800            j9vm.689      > runInternalJVMCheckpointHooks
09:08:44   [OUT] 13:08:25.668 0xd800            j9vm.690      < runInternalJVMCheckpointHooks
09:08:44   [OUT] 13:08:25.668 0xd800            j9vm.732      - Current syslogOptions: error,vital
09:08:44   [OUT] 13:08:25.669 0xd800            j9vm.729      - Before checkpoint criu_dump(), j9time_nano_time() returns 3563579368949547, j9time_current_time_nanos() returns 1730380105669093723
09:08:44   [OUT] 13:08:28.055 0xd800            j9vm.691      > runInternalJVMRestoreHooks
09:08:44   [OUT] 13:08:28.056 0xd800            j9vm.721      - Reset j.l.VirtualThread.ForkJoinPool.parallelism: same cpu count (4) between C/R
09:08:44   [OUT] JVMJITM048W AOT load and compilation disabled pre-checkpoint and post-restore.
09:08:44   [OUT] JVMJITM044W Some or all compiled code in the code cache invalidated post restore.
09:08:44   [OUT] 13:08:28.062 0xd800            j9vm.692      < runInternalJVMRestoreHooks
09:08:44   [OUT] 13:08:28.063 0xd800            j9vm.733      - After checkpoint criu_dump(), j9time_nano_time() returns 3563581763100202, j9time_current_time_nanos() returns 1730380108063244353
09:08:44   [OUT] 13:08:28.063 0xd800            j9vm.734      - After restore, restoreNanoUTCTime = 1730380108063244353, checkpointNanoUTCTime = 1730380097831225383, checkpointRestoreTimeDelta = 10232018970, restoreNanoTimeMonotonic = 3563581763100202, checkpointNanoTimeMonotonic = 3563571531081207, nanoTimeMonotonicClockDelta = 10232018995
09:08:44   [OUT] testTimeCompensation() postRestoreHook checkElapseTime starts, current thread name: main, Thu Oct 31 13:08:30 UTC 2024, System.currentTimeMillis() 1730380111022, System.nanoTime() 3563574490792202
09:08:44   [OUT] testTimeCompensation() postRestoreHook: startMillisTime (1730380095608ms) startNanoTime (3563569308714418ns) currentMillisTime (1730380110817ms) currentNanoTime (3563574285241514ns) elapsedMillisTime (15209ms) elapsedNanoTime (4976527096ns)
09:08:44   [OUT] testTimeCompensation() postRestoreHook checkElapseTime ends, current thread name: main, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111274, System.nanoTime() 3563574742648352
09:08:44   [OUT] 13:08:31.417 0xd800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFF357B8
09:08:44   [OUT] 13:08:31.417 0xd800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFF35DE8
09:08:44   [OUT] 13:08:31.417 0xd800            j9vm.743      < Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
09:08:44   [OUT] testTimeCompensation() after CRIU restore checkElapseTime starts, current thread name: main, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111444, System.nanoTime() 3563574911854452
09:08:44   [OUT] testTimeCompensation() after CRIU restore: startMillisTime (1730380095608ms) startNanoTime (3563569308714418ns) currentMillisTime (1730380111443ms) currentNanoTime (3563574911809078ns) elapsedMillisTime (15835ms) elapsedNanoTime (5603094660ns)
09:08:44   [OUT] testTimeCompensation() after CRIU restore checkElapseTime ends, current thread name: main, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111444, System.nanoTime() 3563574912046450
09:08:44   [OUT] main: Thu Oct 31 13:08:31 UTC 2024, testTimeCompensation() postRestore, System.currentTimeMillis(): 1730380111444, System.nanoTime(): 3563574912113624
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111447, System.nanoTime() 3563574915368958
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 4s: startMillisTime (1730380095608ms) startNanoTime (3563569308439397ns) currentMillisTime (1730380111447ms) currentNanoTime (3563574915325883ns) elapsedMillisTime (15839ms) elapsedNanoTime (5606886486ns)
09:08:44   [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111447, System.nanoTime() 3563574915593405
09:08:44   [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111462, System.nanoTime() 3563574929884723
09:08:44   [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms: startMillisTime (1730380097785ms) startNanoTime (3563571485099366ns) currentMillisTime (1730380111461ms) currentNanoTime (3563574929823274ns) elapsedMillisTime (13676ms) elapsedNanoTime (3444723908ns)
09:08:44   [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111516, System.nanoTime() 3563574984121684
09:08:44   [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111462, System.nanoTime() 3563574929884723
09:08:44   [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms: startMillisTime (1730380111274ms) startNanoTime (3563574742735451ns) currentMillisTime (1730380111461ms) currentNanoTime (3563574929823224ns) elapsedMillisTime (187ms) elapsedNanoTime (187087773ns)
09:08:44   [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111528, System.nanoTime() 3563574996719624
09:08:44   [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111549, System.nanoTime() 3563575017779331
09:08:44   [OUT] testTimeCompensation() postRestore timer delayed 100ms: startMillisTime (1730380111444ms) startNanoTime (3563574912172923ns) currentMillisTime (1730380111549ms) currentNanoTime (3563575017703232ns) elapsedMillisTime (105ms) elapsedNanoTime (105530309ns)
09:08:44   [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Thu Oct 31 13:08:31 UTC 2024, System.currentTimeMillis() 1730380111550, System.nanoTime() 3563575018026053
09:08:44   [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Thu Oct 31 13:08:32 UTC 2024, System.currentTimeMillis() 1730380112024, System.nanoTime() 3563575491844758
09:08:44   [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s: startMillisTime (1730380097785ms) startNanoTime (3563571485480511ns) currentMillisTime (1730380112023ms) currentNanoTime (3563575491745084ns) elapsedMillisTime (14238ms) elapsedNanoTime (4006264573ns)
09:08:44   [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Thu Oct 31 13:08:32 UTC 2024, System.currentTimeMillis() 1730380112024, System.nanoTime() 3563575492152804
09:08:44   [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113422, System.nanoTime() 3563576890813158
09:08:44   [OUT] testTimeCompensation() postRestoreHook timer delayed 2s: startMillisTime (1730380111417ms) startNanoTime (3563574884983119ns) currentMillisTime (1730380113422ms) currentNanoTime (3563576890715259ns) elapsedMillisTime (2005ms) elapsedNanoTime (2005732140ns)
09:08:44   [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113423, System.nanoTime() 3563576891114429
09:08:44   [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 2s, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113450, System.nanoTime() 3563576917912764
09:08:44   [OUT] testTimeCompensation() postRestore timer delayed 2s: startMillisTime (1730380111444ms) startNanoTime (3563574912586293ns) currentMillisTime (1730380113449ms) currentNanoTime (3563576917798315ns) elapsedMillisTime (2005ms) elapsedNanoTime (2005212022ns)
09:08:44   [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 2s, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113450, System.nanoTime() 3563576918225485
09:08:44   [OUT] testTimeCompensation() postRestore checkElapseTime starts, current thread name: main, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113468, System.nanoTime() 3563576936025484
09:08:44   [OUT] testTimeCompensation() postRestore: startMillisTime (1730380111444ms) startNanoTime (3563574912155673ns) currentMillisTime (1730380113468ms) currentNanoTime (3563576935949435ns) elapsedMillisTime (2024ms) elapsedNanoTime (2023793762ns)
09:08:44   [OUT] testTimeCompensation() postRestore checkElapseTime ends, current thread name: main, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113468, System.nanoTime() 3563576936181182
09:08:44   [OUT] getResultAndCancelTimers before Thread.yield() taskRunning = 0, current thread name: main, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113837, System.nanoTime() 3563577305159219
09:08:44   [OUT] getResultAndCancelTimers before timer.cancel(), current thread name: main, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113837, System.nanoTime() 3563577305303467
09:08:44   [OUT] TimeTestTask tasksPassed: true, taskStarted: 9, taskExecuted: 8, current thread name: main, Thu Oct 31 13:08:33 UTC 2024, System.currentTimeMillis() 1730380113961, System.nanoTime() 3563577429673387
09:08:44   [OUT] FAILED: testTimeCompensation
09:08:44   [OUT] initiate restore
09:08:44   [OUT] Removed test output files
09:08:44   [OUT] finished script
09:08:44   [ERR] /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_aarch64_linux_OMR_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 3926654 Killed                  $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
09:08:44  >> Success condition was found: [Output match: Killed]
09:08:44  >> Success condition was not found: [Output match: PASSED: testTimeCompensation]
09:08:44  >> Failure condition was not found: [Output match: CRIU is not enabled]
09:08:44  >> Failure condition was not found: [Output match: Operation not permitted]
09:08:44  >> Failure condition was found: [Output match: FAILED: testTimeCompensation]
09:08:44  >> Success condition was not found: [Output match: Thread pid mismatch]
09:08:44  >> Success condition was not found: [Output match: do not match expected]
09:08:44  >> Success condition was not found: [Output match: Unable to create a thread:]
09:08:44  >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
09:08:44  >> Failure condition was not found: [Output match: User requested Java dump using]
09:08:44  >> Failure condition was not found: [Output match: AOT load and compilation disabled post restore]
github-actions[bot] commented 6 days ago

Issue Number: 20464 Status: Open Recommended Components: comp:vm, comp:test, comp:gc Recommended Assignees: jasonfengj9, tajila, babsingh

pshipton commented 22 hours ago

https://openj9-jenkins.osuosl.org/job/Test_openjdk21_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/234/ cmdLineTester_criu_nonPortableRestore_1

18:13:51  Testing: Create CRIU checkpoint image and restore once - testTimeCompensation
18:13:51  Test start time: 2024/11/04 23:13:50 Coordinated Universal Time
18:13:51  Running command: bash /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/jdkbinary/j2sdk-image/bin/java " -Xint -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9jcl.533,j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED" org.openj9.criu.TimeChangeTest testTimeCompensation 1 false false
18:13:51  Time spent starting: 2 milliseconds
18:13:59  Time spent executing: 8514 milliseconds
18:13:59  Test result: FAILED
18:13:59  Output from test:
18:13:59   [OUT] start running script
18:13:59   [OUT] export GLIBC_TUNABLES=glibc.cpu.hwcaps=-XSAVEC,-XSAVE,-AVX2,-ERMS,-AVX,-AVX_Fast_Unaligned_Load
18:13:59   [OUT] export LD_BIND_NOT=on
18:13:59   [OUT] /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/jdkbinary/j2sdk-image/bin/java -XX:+EnableCRIUSupport  -Xint -XX:+CRIURestoreNonPortableMode  -Xtrace:print={j9jcl.533,j9vm.684-696,j9vm.699,j9vm.717-743} --add-exports java.base/openj9.internal.criu=ALL-UNNAMED -cp /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criu.jar org.openj9.criu.TimeChangeTest testTimeCompensation 1
18:13:59   [OUT] main: Mon Nov 04 23:13:50 UTC 2024, testTimeCompensation() starts, System.currentTimeMillis(): 1730762030800, System.nanoTime(): 3342715433189007
18:13:59   [OUT] testTimeCompensation() sleep 100ms checkElapseTime starts, current thread name: main, Mon Nov 04 23:13:50 UTC 2024, System.currentTimeMillis() 1730762030992, System.nanoTime() 3342715625317434
18:13:59   [OUT] testTimeCompensation() sleep 100ms: startMillisTime (1730762030890ms) startNanoTime (3342715522882379ns) currentMillisTime (1730762030990ms) currentNanoTime (3342715622993287ns) elapsedMillisTime (100ms) elapsedNanoTime (100110908ns)
18:13:59   [OUT] testTimeCompensation() sleep 100ms checkElapseTime ends, current thread name: main, Mon Nov 04 23:13:51 UTC 2024, System.currentTimeMillis() 1730762031026, System.nanoTime() 3342715658540469
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Mon Nov 04 23:13:51 UTC 2024, System.currentTimeMillis() 1730762031126, System.nanoTime() 3342715759246617
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms: startMillisTime (1730762031026ms) startNanoTime (3342715658620738ns) currentMillisTime (1730762031126ms) currentNanoTime (3342715759133841ns) elapsedMillisTime (100ms) elapsedNanoTime (100513103ns)
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 100ms, Mon Nov 04 23:13:51 UTC 2024, System.currentTimeMillis() 1730762031127, System.nanoTime() 3342715759600779
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Mon Nov 04 23:13:53 UTC 2024, System.currentTimeMillis() 1730762033027, System.nanoTime() 3342717659609262
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 2s: startMillisTime (1730762031026ms) startNanoTime (3342715659013059ns) currentMillisTime (1730762033027ms) currentNanoTime (3342717659478865ns) elapsedMillisTime (2001ms) elapsedNanoTime (2000465806ns)
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 2s, Mon Nov 04 23:13:53 UTC 2024, System.currentTimeMillis() 1730762033027, System.nanoTime() 3342717660034730
18:13:59   [OUT] testTimeCompensation() preCheckpoint checkElapseTime starts, current thread name: main, Mon Nov 04 23:13:53 UTC 2024, System.currentTimeMillis() 1730762033030, System.nanoTime() 3342717663082710
18:13:59   [OUT] testTimeCompensation() preCheckpoint: startMillisTime (1730762031026ms) startNanoTime (3342715659297021ns) currentMillisTime (1730762033030ms) currentNanoTime (3342717663037019ns) elapsedMillisTime (2004ms) elapsedNanoTime (2003739998ns)
18:13:59   [OUT] testTimeCompensation() preCheckpoint checkElapseTime ends, current thread name: main, Mon Nov 04 23:13:53 UTC 2024, System.currentTimeMillis() 1730762033030, System.nanoTime() 3342717663305852
18:13:59   [OUT] main: Mon Nov 04 23:13:53 UTC 2024, Performing CRIUSupport.checkpointJVM(), System.currentTimeMillis(): 1730762033031, System.nanoTime(): 3342717663413419
18:13:59   [OUT] 23:13:53.052*0x95800            j9vm.728      > Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
18:13:59   [OUT] 23:13:53.052 0x95800            j9vm.727      - Taking a checkpoint with active clinit
18:13:59   [OUT] 23:13:53.052 0x95800            j9vm.684      > initializeCriuHooks
18:13:59   [OUT] 23:13:53.052 0x95800            j9vm.720      - initializeCriuHooks() checkpoint CPU count (4)
18:13:59   [OUT] 23:13:53.052 0x95800            j9vm.723    * - initializeCriuHooks() j.u.Random class not found
18:13:59   [OUT] 23:13:53.052 0x95800            j9vm.717      < initializeCriuHooks - checkpointState.hookRecords (00007FFF8029D410), classIterationRestoreHookRecords (00007FFF8029E550), delayedLockingOperationsRecords (00007FFF8029F690)
18:13:59   [OUT] testTimeCompensation() preCheckpointHook checkElapseTime starts, current thread name: main, Mon Nov 04 23:13:53 UTC 2024, System.currentTimeMillis() 1730762033052, System.nanoTime() 3342717684804603
18:13:59   [OUT] testTimeCompensation() preCheckpointHook: startMillisTime (1730762031026ms) startNanoTime (3342715659297021ns) currentMillisTime (1730762033052ms) currentNanoTime (3342717684723377ns) elapsedMillisTime (2026ms) elapsedNanoTime (2025426356ns)
18:13:59   [OUT] testTimeCompensation() preCheckpointHook checkElapseTime ends, current thread name: main, Mon Nov 04 23:13:53 UTC 2024, System.currentTimeMillis() 1730762033052, System.nanoTime() 3342717685048482
18:13:59   [OUT] 23:13:53.052 0x95800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFEE1320
18:13:59   [OUT] 23:13:53.053 0x95800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFEE1930
18:13:59   [OUT] 23:13:53.053 0x95800            j9vm.730      - Before checkpoint, checkpointNanoTimeMonotonic = 3342717686243417, checkpointNanoUTCTime = 1730762033053876008
18:13:59   [OUT] 23:13:53.069 0x95800            j9vm.689      > runInternalJVMCheckpointHooks
18:13:59   [OUT] 23:13:53.071 0x95800            j9vm.690      < runInternalJVMCheckpointHooks
18:13:59   [OUT] 23:13:53.071 0x95800            j9vm.732      - Current syslogOptions: error,vital
18:13:59   [OUT] 23:13:53.071 0x95800            j9vm.729      - Before checkpoint criu_dump(), j9time_nano_time() returns 3342717703511314, j9time_current_time_nanos() returns 1730762033071143899
18:13:59   [OUT] 23:13:55.129 0x95800            j9vm.691      > runInternalJVMRestoreHooks
18:13:59   [OUT] 23:13:55.129 0x95800            j9vm.721      - Reset j.l.VirtualThread.ForkJoinPool.parallelism: same cpu count (4) between C/R
18:13:59   [OUT] 23:13:55.130 0x95800            j9vm.692      < runInternalJVMRestoreHooks
18:13:59   [OUT] 23:13:55.130 0x95800            j9vm.733      - After checkpoint criu_dump(), j9time_nano_time() returns 3342719762565844, j9time_current_time_nanos() returns 1730762035130198417
18:13:59   [OUT] 23:13:55.130 0x95800            j9vm.734      - After restore, restoreNanoUTCTime = 1730762035130198417, checkpointNanoUTCTime = 1730762033053876008, checkpointRestoreTimeDelta = 2076322409, restoreNanoTimeMonotonic = 3342719762565844, checkpointNanoTimeMonotonic = 3342717686243417, nanoTimeMonotonicClockDelta = 2076322427
18:13:59   [OUT] testTimeCompensation() postRestoreHook checkElapseTime starts, current thread name: main, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035136, System.nanoTime() 3342717692243538
18:13:59   [OUT] testTimeCompensation() postRestoreHook: startMillisTime (1730762031026ms) startNanoTime (3342715659297021ns) currentMillisTime (1730762035136ms) currentNanoTime (3342717692187642ns) elapsedMillisTime (4110ms) elapsedNanoTime (2032890621ns)
18:13:59   [OUT] testTimeCompensation() postRestoreHook checkElapseTime ends, current thread name: main, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035136, System.nanoTime() 3342717692470569
18:13:59   [OUT] 23:13:55.136 0x95800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFEF6190
18:13:59   [OUT] 23:13:55.136 0x95800            j9vm.696      - Checkpoint thread calling lock-related op=1 on instance=00000000FFEF67A0
18:13:59   [OUT] 23:13:55.136 0x95800            j9vm.743      < Java_openj9_internal_criu_CRIUSupport_checkpointJVMImpl
18:13:59   [OUT] testTimeCompensation() after CRIU restore checkElapseTime starts, current thread name: main, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035137, System.nanoTime() 3342717693097100
18:13:59   [OUT] testTimeCompensation() after CRIU restore: startMillisTime (1730762031026ms) startNanoTime (3342715659297021ns) currentMillisTime (1730762035137ms) currentNanoTime (3342717693046548ns) elapsedMillisTime (4111ms) elapsedNanoTime (2033749527ns)
18:13:59   [OUT] testTimeCompensation() after CRIU restore checkElapseTime ends, current thread name: main, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035137, System.nanoTime() 3342717693292862
18:13:59   [OUT] main: Mon Nov 04 23:13:55 UTC 2024, testTimeCompensation() postRestore, System.currentTimeMillis(): 1730762035137, System.nanoTime(): 3342717693395511
18:13:59   [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035140, System.nanoTime() 3342717696151262
18:13:59   [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms: startMillisTime (1730762033052ms) startNanoTime (3342717685136668ns) currentMillisTime (1730762035140ms) currentNanoTime (3342717696104049ns) elapsedMillisTime (2088ms) elapsedNanoTime (10967381ns)
18:13:59   [OUT] testTimeCompensation()() preCheckpointHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation()() preCheckpointHook timer delayed 10ms, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035140, System.nanoTime() 3342717696516224
18:13:59   [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035147, System.nanoTime() 3342717703165234
18:13:59   [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms: startMillisTime (1730762035136ms) startNanoTime (3342717692546981ns) currentMillisTime (1730762035147ms) currentNanoTime (3342717703103254ns) elapsedMillisTime (11ms) elapsedNanoTime (10556273ns)
18:13:59   [OUT] testTimeCompensation() postRestoreHook timer delayed 10ms checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 10ms, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035147, System.nanoTime() 3342717703397547
18:13:59   [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035238, System.nanoTime() 3342717794088828
18:13:59   [OUT] testTimeCompensation() postRestore timer delayed 100ms: startMillisTime (1730762035137ms) startNanoTime (3342717693500579ns) currentMillisTime (1730762035237ms) currentNanoTime (3342717793975727ns) elapsedMillisTime (100ms) elapsedNanoTime (100475148ns)
18:13:59   [OUT] testTimeCompensation() postRestore timer delayed 100ms checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 100ms, Mon Nov 04 23:13:55 UTC 2024, System.currentTimeMillis() 1730762035238, System.nanoTime() 3342717794373084
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037103, System.nanoTime() 3342719659868826
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 4s: startMillisTime (1730762031026ms) startNanoTime (3342715659117310ns) currentMillisTime (1730762037103ms) currentNanoTime (3342719659747736ns) elapsedMillisTime (6077ms) elapsedNanoTime (4000630426ns)
18:13:59   [OUT] testTimeCompensation() preCheckpoint timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpoint timer delayed 4s, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037104, System.nanoTime() 3342719660162900
18:13:59   [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestore timer delayed 2s, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037137, System.nanoTime() 3342719693197386
18:13:59   [OUT] testTimeCompensation() postRestore timer delayed 2s: startMillisTime (1730762035137ms) startNanoTime (3342717693644694ns) currentMillisTime (1730762037137ms) currentNanoTime (3342719693129105ns) elapsedMillisTime (2000ms) elapsedNanoTime (1999484411ns)
18:13:59   [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime starts, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037137, System.nanoTime() 3342719693197380
18:13:59   [OUT] testTimeCompensation() postRestoreHook timer delayed 2s: startMillisTime (1730762035136ms) startNanoTime (3342717692743833ns) currentMillisTime (1730762037137ms) currentNanoTime (3342719693129286ns) elapsedMillisTime (2001ms) elapsedNanoTime (2000385453ns)
18:13:59   [OUT] testTimeCompensation() postRestore timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestore timer delayed 2s, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037137, System.nanoTime() 3342719693448323
18:13:59   [OUT] testTimeCompensation() postRestoreHook timer delayed 2s checkElapseTime ends, current thread name: testTimeCompensation() postRestoreHook timer delayed 2s, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037137, System.nanoTime() 3342719693696977
18:13:59   [OUT] testTimeCompensation() postRestore checkElapseTime starts, current thread name: main, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037138, System.nanoTime() 3342719694114257
18:13:59   [OUT] testTimeCompensation() postRestore: startMillisTime (1730762035137ms) startNanoTime (3342717693494391ns) currentMillisTime (1730762037138ms) currentNanoTime (3342719694071438ns) elapsedMillisTime (2001ms) elapsedNanoTime (2000577047ns)
18:13:59   [OUT] testTimeCompensation() postRestore checkElapseTime ends, current thread name: main, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037138, System.nanoTime() 3342719694312501
18:13:59   [OUT] getResultAndCancelTimers before Thread.yield() taskRunning = 1, current thread name: main, Mon Nov 04 23:13:57 UTC 2024, System.currentTimeMillis() 1730762037149, System.nanoTime() 3342719705825657
18:13:59   [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime starts, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Mon Nov 04 23:13:59 UTC 2024, System.currentTimeMillis() 1730762039130, System.nanoTime() 3342721686285659
18:13:59   [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s: startMillisTime (1730762033052ms) startNanoTime (3342717685346316ns) currentMillisTime (1730762039130ms) currentNanoTime (3342721686146372ns) elapsedMillisTime (6078ms) elapsedNanoTime (4000800056ns)
18:13:59   [OUT] testTimeCompensation() preCheckpointHook timer delayed 4s checkElapseTime ends, current thread name: testTimeCompensation() preCheckpointHook timer delayed 4s, Mon Nov 04 23:13:59 UTC 2024, System.currentTimeMillis() 1730762039130, System.nanoTime() 3342721686646940
18:13:59   [OUT] getResultAndCancelTimers before timer.cancel(), current thread name: main, Mon Nov 04 23:13:59 UTC 2024, System.currentTimeMillis() 1730762039130, System.nanoTime() 3342721686813182
18:13:59   [OUT] TimeTestTask tasksPassed: true, taskStarted: 9, taskExecuted: 8, current thread name: main, Mon Nov 04 23:13:59 UTC 2024, System.currentTimeMillis() 1730762039147, System.nanoTime() 3342721703416437
18:13:59   [OUT] FAILED: testTimeCompensation
18:13:59   [OUT] initiate restore
18:13:59   [OUT] Removed test output files
18:13:59   [OUT] finished script
18:13:59   [ERR] /home/jenkins/workspace/Test_openjdk21_j9_sanity.functional_ppc64le_linux_Nightly_testList_0/aqa-tests/TKG/../../jvmtest/functional/cmdLineTests/criu/criuScript.sh: line 41: 444416 Killed                  $2 -XX:+EnableCRIUSupport $3 -cp "$1/criu.jar" $4 $5 $6 > testOutput 2>&1
18:13:59  >> Success condition was found: [Output match: Killed]
18:13:59  >> Success condition was not found: [Output match: PASSED: testTimeCompensation]
18:13:59  >> Failure condition was not found: [Output match: CRIU is not enabled]
18:13:59  >> Failure condition was not found: [Output match: Operation not permitted]
18:13:59  >> Failure condition was found: [Output match: FAILED: testTimeCompensation]
18:13:59  >> Success condition was not found: [Output match: Thread pid mismatch]
18:13:59  >> Success condition was not found: [Output match: do not match expected]
18:13:59  >> Success condition was not found: [Output match: Unable to create a thread:]
18:13:59  >> Failure condition was not found: [Output match: Could not dump the JVM processes, err=-70]
18:13:59  >> Failure condition was not found: [Output match: User requested Java dump using]
18:13:59  >> Failure condition was not found: [Output match: AOT load and compilation disabled post restore]
pshipton commented 22 hours ago

@tajila fyi