Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

CRIU testTimeCompensation failure taskStarted: 9, taskExecuted: 8 #20464

Closed
pshipton opened this issue Oct 31, 2024 · 7 comments · Fixed by #20638
Closed

CRIU testTimeCompensation failure taskStarted: 9, taskExecuted: 8 #20464

pshipton opened this issue Oct 31, 2024 · 7 comments · Fixed by #20638
Assignees
@JasonFengJ9
Labels
criu Used to track CRIU snapshot related work test failure

Comments

@pshipton
Copy link
Member

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]
@pshipton pshipton added test failure criu Used to track CRIU snapshot related work labels Oct 31, 2024
@github-actions GitHub Actions
Copy link

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

@pshipton
Copy link
Member Author

pshipton commented Nov 5, 2024

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
Copy link
Member Author

pshipton commented Nov 5, 2024

@tajila fyi

@pshipton
Copy link
Member Author

https://openj9-jenkins.osuosl.org/job/Test_openjdk23_j9_sanity.functional_ppc64le_linux_Nightly_testList_1/32

@JasonFengJ9
Copy link
Member

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

There were 9 sub-test scenarios, and none of them reported failure.
taskExecuted was 8 not matching taskStarted: 9, there might be an issue with the test.

@pshipton
Copy link
Member Author

https://openj9-jenkins.osuosl.org/job/Test_openjdk17_j9_sanity.functional_ppc64le_linux_Nightly_testList_1/711

@pshipton pshipton changed the title CRIU testTimeCompensation failure CRIU testTimeCompensation failure taskStarted: 9, taskExecuted: 8 Nov 18, 2024
@JasonFengJ9 JasonFengJ9 mentioned this issue Nov 19, 2024
Merged
@github-actions GitHub Actions
Copy link

Issue Number: 20464
Status: Closed
Actual Components: test failure, criu
Actual Assignees: No one :(
PR Assignees: JasonFengJ9

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

@JasonFengJ9 JasonFengJ9

Labels
criu Used to track CRIU snapshot related work test failure
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix TimeUtilities thread number counting synchronization JasonFengJ9/openj9
2 participants
@JasonFengJ9 @pshipton